[PROBLEM] moOde does not appear to notice when ashuffle fails to start

[cricalix]

In http://moodeaudio.org/forum/showthread.php?tid=3845 I was hitting issues with shuffle not working.

Then I got it working briefly while rebuilding the mpd database.

Now the rebuild has finished, ashuffle doesn't work any more.

ashuffle is exiting with status code 1 set in the shell, and "MPD error: Response line too large" in the output.

That line ties to https://github.com/joshkunz/ashuffle/issues/89. I've checked with the various shell commands, and the longest data line from my library is 1500 bytes or so, but I could see a case where multiple of these ended up in the buffer (I've not read libmpdclient's code to be sure), and caused an overflow.

Unfortunately, the moOde UI (and debug logs) give no indication that ashuffle failed to start up when shuffle mode is selected.

Wasn't sure whether to post this here or on the github issues for the project.

[cricalix]

As a thought for the whole startup and being able to get the status - ashuffle ships with a default systemd config that can be used as a system level config instead of a user level config (https://github.com/joshkunz/ashuffle/pull/75/files).

I've done a quick test that proves that this systemd config works. Putting in the filters etc via the override.conf feature of systemd should hypothetically work; the override just rewrites the ExecStart with all the additional bits.

Once the service is started, the status can be checked easily enough with systemctl status ashuffle.service or systemctl is-active ashuffle.service, and on failure (which could then potentially be passed to the web ui?), the status looks like:

Code:

● ashuffle.service - Shuffle service for mpd
  Loaded: loaded (/lib/systemd/system/ashuffle.service; enabled; vendor preset: enabled)
 Drop-In: /etc/systemd/system/ashuffle.service.d
          └─override.conf
  Active: failed (Result: exit-code) since Sun 2021-05-23 20:55:14 IST; 18s ago
 Process: 11668 ExecStart=/usr/local/bin/ashuffle --queue-buffer 2 (code=exited, status=1/FAILURE)
Main PID: 11668 (code=exited, status=1/FAILURE)

May 23 20:55:06 moode systemd[1]: Started Shuffle service for mpd.
May 23 20:55:14 moode ashuffle[11668]: libmpdclient received a malformed response from the server.
May 23 20:55:14 moode ashuffle[11668]: This may be because a song's metadata attribute (for example,
May 23 20:55:14 moode ashuffle[11668]: a comment) was longer than 4KiB.
May 23 20:55:14 moode ashuffle[11668]: See https://github.com/joshkunz/ashuffle/issues/89 for
May 23 20:55:14 moode ashuffle[11668]: details or updates.
May 23 20:55:14 moode ashuffle[11668]: MPD error: Response line too large
May 23 20:55:14 moode systemd[1]: ashuffle.service: Main process exited, code=exited, status=1/FAILURE
May 23 20:55:14 moode systemd[1]: ashuffle.service: Failed with result 'exit-code'.

[Tim Curtis]

In http://moodeaudio.org/forum/showthread.php?tid=3845 I was hitting issues with shuffle not working.

Then I got it working briefly while rebuilding the mpd database.

Now the rebuild has finished, ashuffle doesn't work any more.

ashuffle is exiting with status code 1 set in the shell, and "MPD error: Response line too large" in the output.

That line ties to https://github.com/joshkunz/ashuffle/issues/89. I've checked with the various shell commands, and the longest data line from my library is 1500 bytes or so, but I could see a case where multiple of these ended up in the buffer (I've not read libmpdclient's code to be sure), and caused an overflow.

Unfortunately, the moOde UI (and debug logs) give no indication that ashuffle failed to start up when shuffle mode is selected.

Wasn't sure whether to post this here or on the github issues for the project.

Ashuffle runs independently of MPD in the background. It's similar to the audio renderers for example Shairport-sync, librespot, squeezelite, etc., which are all independent of MPD and run in the background. This makes it a challenge to monitor them and trap/report errors.

It could prolly be done by adding some code to /var/www/command/watchdog.sh that checks to see if ashuffle was activated and then checks to see if the ashuffle process is running. If its not running then write "Ashuffle activated but not running" to the Moode startup log. Something like that.

I think if there were many reports of ashuffle failing it would prolly be justified to add the code to watchdog.sh but generally ashuffle works. It's just the rare situation of a track having > 4K amount of metadata that causes it to bomb.

[Tim Curtis]

As a thought for the whole startup and being able to get the status - ashuffle ships with a default systemd config that can be used as a system level config instead of a user level config (https://github.com/joshkunz/ashuffle/pull/75/files).

I've done a quick test that proves that this systemd config works. Putting in the filters etc via the override.conf feature of systemd should hypothetically work; the override just rewrites the ExecStart with all the additional bits.

Once the service is started, the status can be checked easily enough with systemctl status ashuffle.service or systemctl is-active ashuffle.service, and on failure (which could then potentially be passed to the web ui?), the status looks like:

Code:

● ashuffle.service - Shuffle service for mpd
  Loaded: loaded (/lib/systemd/system/ashuffle.service; enabled; vendor preset: enabled)
 Drop-In: /etc/systemd/system/ashuffle.service.d
          └─override.conf
  Active: failed (Result: exit-code) since Sun 2021-05-23 20:55:14 IST; 18s ago
 Process: 11668 ExecStart=/usr/local/bin/ashuffle --queue-buffer 2 (code=exited, status=1/FAILURE)
Main PID: 11668 (code=exited, status=1/FAILURE)

May 23 20:55:06 moode systemd[1]: Started Shuffle service for mpd.
May 23 20:55:14 moode ashuffle[11668]: libmpdclient received a malformed response from the server.
May 23 20:55:14 moode ashuffle[11668]: This may be because a song's metadata attribute (for example,
May 23 20:55:14 moode ashuffle[11668]: a comment) was longer than 4KiB.
May 23 20:55:14 moode ashuffle[11668]: See https://github.com/joshkunz/ashuffle/issues/89 for
May 23 20:55:14 moode ashuffle[11668]: details or updates.
May 23 20:55:14 moode ashuffle[11668]: MPD error: Response line too large
May 23 20:55:14 moode systemd[1]: ashuffle.service: Main process exited, code=exited, status=1/FAILURE
May 23 20:55:14 moode systemd[1]: ashuffle.service: Failed with result 'exit-code'.

Currently it's started/stopped via some functions in /var/www/inc/playerlib.php

Code:

// Auto-shuffle random play
function startAutoShuffle() {
    $ashuffle_filter = (!empty($_SESSION['ashuffle_filter']) && $_SESSION['ashuffle_filter'] != 'None') ?
        'mpc search ' . $_SESSION['ashuffle_filter'] . ' | ' : '';
    $ashuffle_file = $ashuffle_filter != '' ? '--file -' : '';
    $ashuffle_mode = $_SESSION['ashuffle_mode'] == 'Album' ? '--group-by album ' : '';
    $result = sysCmd($ashuffle_filter . '/usr/local/bin/ashuffle --queue-buffer 1 ' . $ashuffle_mode . $ashuffle_file . ' > /dev/null 2>&1 &');
}
function stopAutoShuffle() {
    sysCmd('killall -s 9 ashuffle > /dev/null');
    playerSession('write', 'ashuffle', '0');
    if (false === ($sock = openMpdSock('localhost', 6600))) {
        workerLog('stopAutoShuffle(): MPD connect failed');
        exit(0);
    }
    sendMpdCmd($sock, 'consume 0');
    $resp = readMpdResp($sock);
    closeMpdSock($sock);
}

[cricalix]

Ashuffle runs independently of MPD in the background. It's similar to the audio renderers for example Shairport-sync, librespot, squeezelite, etc., which are all independent of MPD and run in the background. This makes it a challenge to monitor them and trap/report errors.

It could prolly be done by adding some code to /var/www/command/watchdog.sh that checks to see if ashuffle was activated and then checks to see if the ashuffle process is running. If its not running then write "Ashuffle activated but not running" to the Moode startup log. Something like that.

I think if there were many reports of ashuffle failing it would prolly be justified to add the code to watchdog.sh but generally ashuffle works. It's just the rare situation of a track having > 4K amount of metadata that causes it to bomb.

Yeah, I'm really not sure it's a single 4k metadata that's causing it in my case; I can't find tracks with any single tag having > 4096 bytes of data, but perhaps there's some with > 4096 across all tags on the file and libmpdclient is trying to fit all of that in the buffer. I have found that calling ashuffle with -n causes it to not do a validation check against mpd, so I can sort of work around this with a search for filename NAS in the autoshuffle configuration, which startAutoShuffle() should then use as a mpc search filter to pass to ashuffle (and I can manually customise that startup command to have -n as well as --queue-buffer 1). Bit of a hack, but at least posting it here means that someone else who hits this has a chance of trying a hacky fix.

I grok that ashuffle is being spun off in the background - I've dug through playerlib.php to see how ashuffle was being started and noted the backgrounding. The idea of sticking it in systemd is you then get systemd to manage it in the background, and then all of the status/info/is-active commands become available for simple checking.