Reproducible crash while playing

[jvromans@squirrel.nl]

I can reproducibly crash LMS when playing a certain album.

No, this is not the most recent LMS (it is version 7.9.1-168 from the
Synology 3rd party repository). This may be a good time to consider
upgrading to a newer LMS (although... which one?) Nevertheless I am curious
what could be the cause of the crash.

The crash happens when I use Spotty to play the Lankum album "Cold Old
Fire". A couple of seconds after switching from track 7 to track 8 the
Squeezebox goes silent because of a crashed server. I can play track 7 w/o
problems. I can play track 8 w/o problems. But I can not play tracks 7 and
8 in sequence.

There is nothing relevant in the server log.

Ideas?

[mherger]

> No, this is not the most recent LMS (it is version 7.9.1-168 from the
> Synology 3rd party repository). This may be a good time to consider
> upgrading to a newer LMS (although... which one?) Nevertheless I am curious
> what could be the cause of the crash.

Could you reproduce the same issue eg. on your desktop? Could you please
enable logging for plugin.spotty=INFO, reproduce, send me the log file:

https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a

(check out pinkdot's thread about his Synology packages)

--

Michael

[jvromans@squirrel.nl]

On Mon, 30 Sep 2019 06:37:10 +0200, Michael Herger <slim (AT) herger (DOT) net> wrote:

> Could you reproduce the same issue eg. on your desktop? Could you please
> enable logging for plugin.spotty=INFO, reproduce, send me
> the log file:

Do you mean log4perl.logger.plugin.spotty=INFO in log.prefs?

[mherger]

> Do you mean log4perl.logger.plugin.spotty=INFO in log.prefs?

Don't mess with the prefs file, just go to Settings/Advanced/Logging.

--

Michael

[jvromans@squirrel.nl]

On Mon, 30 Sep 2019 09:01:12 +0200, Michael Herger <slim (AT) herger (DOT) net> wrote:

> > Do you mean log4perl.logger.plugin.spotty=INFO in log.prefs?
>
> Don't mess with the prefs file, just go to Settings/Advanced/Logging.
>

Clear.

It doesn't help. There are some messages and then the server disappears.

So I ran the server from the command line and then I see this:

[19-09-30 09:43:38.1620] main::init (387) Starting Logitech Media Server (v7.9.1, 1504317335, Mon Sep 4 22:13:00 UTC 2017) perl 5.024000 - aarch64-linux
[19-09-30 09:43:40.1606] Plugins::Spotty::Plugin:urgeAudioCache (464) Starting audio cache cleanup...
[19-09-30 09:43:40.1620] Plugins::Spotty::Plugin:urgeAudioCache (487) Max. cache size is: 0MB, current cache size is 0MB
[19-09-30 09:43:40.1626] Plugins::Spotty::Plugin:urgeAudioCache (518) Starting temporary file cleanup... (/volume1/@appstore/SqueezeCenter/Cache/spotty)
[19-09-30 09:43:40.1632] Plugins::Spotty::Plugin:urgeAudioCache (538) Audio cache cleanup done!
[19-09-30 09:43:42.0017] Plugins::Spotty::Plugin::findBin (775) Trying helper applicaton: /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpottyAARCH64Bin/Bin/spotty-custom
[19-09-30 09:43:42.0480] Plugins::Spotty::Plugin::findBin (778) Found helper applicaton: /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpottyAARCH64Bin/Bin/spotty-custom
[19-09-30 09:43:43.4150] Plugins::Spotty::API::__ANON__ (1374) Trying to read from cache for me
[19-09-30 09:43:43.4158] Plugins::Spotty::API::__ANON__ (1383) API call: me
[19-09-30 09:43:43.5037] Plugins::Spotty::API::__ANON__ (1428) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[19-09-30 09:43:43.5047] Plugins::Spotty::API::__ANON__ (1430) Data cached (https://api.spotify.com/v1/me)
[19-09-30 09:43:56.0379] Plugins::Spotty::Plugin:urgeAudioCacheAfterXTracks (450) Played 1 song(s) since last audio cache purge.
[19-09-30 09:44:01.9382] Plugins::Spotty::Plugin:urgeAudioCacheAfterXTracks (450) Played 2 song(s) since last audio cache purge.
[19-09-30 09:44:09.4663] Plugins::Spotty::Plugin:urgeAudioCacheAfterXTracks (450) Played 3 song(s) since last audio cache purge.
Out of memory!
[19-09-30 09:44:20.5985] Plugins::Spotty::Plugin::renameCacheFolder (369) Trying to rename __AUTHENTICATE__ to

The "out of memory" exit explains why there is no further sign of what went wrong...

[mherger]

> The "out of memory" exit explains why there is no further sign of what went wrong...

Are you saying LMS dies with a OOM?

--

Michael

[jvromans@squirrel.nl]

On Mon, 30 Sep 2019 09:59:08 +0200, Michael Herger <slim (AT) herger (DOT) net> wrote:

> > The "out of memory" exit explains why there is no further sign of what
> > went wrong...
>
> Are you saying LMS dies with a OOM?
>

That seems to be an obvious conclusion, yes.

[bpa]

On Mon, 30 Sep 2019 09:59:08 +0200, Michael Herger <slim (AT) herger (DOT) net> wrote:

> > The "out of memory" exit explains why there is no further sign of what
> > went wrong...
>
> Are you saying LMS dies with a OOM?
>

That seems to be an obvious conclusion, yes.

From a command line "Out of memory" can come from any subprocess (e.g. transcoding, helper apps) so do not assume it comes from LMS.

[jvromans@squirrel.nl]

On Mon, 30 Sep 2019 09:12:18 +0000, bpa
<bpa.976ipb (AT) no-mx (DOT) forums.slimdevices.com> wrote:

> From a command line "Out of memory" can come from any subprocess (e.g.
> transcoding, helper apps) so do not assume it comes from LMS.

I do not assume anything.
I run LMS on the command line (no daemon), and after the "Out of Memory"
message LMS is gone. However, the exit code = 0 (not 12).

So somehow if a helper process goes OOM, then LMS does exit(0) without
notice?

Does the final message

Plugins::Spotty::Plugin::renameCacheFolder (369) Trying to rename __AUTHENTICATE__ to

indicate anything (there is no target name)?

[bpa]

On Mon, 30 Sep 2019 09:12:18 +0000, bpa
<bpa.976ipb (AT) no-mx (DOT) forums.slimdevices.com> wrote:

> From a command line "Out of memory" can come from any subprocess (e.g.
> transcoding, helper apps) so do not assume it comes from LMS.

I do not assume anything.
I run LMS on the command line (no daemon), and after the "Out of Memory"
message LMS is gone. However, the exit code = 0 (not 12).

After googling "Out of memory!" looks to be a genuine Perl error.
The assumption then is that spotty has done something to cause this problem . I think plugin reads a file from spotty.
Perhaps you should check for large files in /volume1/@appstore/SqueezeCenter/Cache/spotty.
The log showed Max cache size as 0Mb ?
[19-09-30 09:43:40.1620] Plugins::Spotty::Plugin:urgeAudioCache (487) Max. cache size is: 0MB, current cache size is 0MB
[19-09-30 09:43:40.1626] Plugins::Spotty::Plugin:urgeAudioCache (518) Starting temporary file cleanup... (/volume1/@appstore/SqueezeCenter/Cache/spotty)