moodeaudio.org > Moode Forum › moOde audio player › Support v
[PROBLEM] [PROBLEM] 9.x: MPD crashing ad-hoc / stops playing

Thank you for your donation!


Cloudsmith graciously provides open-source package management and distribution for our project.


Thread Closed 
Thread Modes
Problem: [PROBLEM] 9.x: MPD crashing ad-hoc / stops playing
the_bertrum Online
Senior Member+
*
Posts: 1,870
Threads: 43
Joined: Mar 2020
Reputation: 85
#71
10-25-2024, 06:12 PM
I tried that Super7 station with my simple mod th mpdmon.php.  Seems to work OK for me.

Code:
Oct 25 19:04 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 19:04 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 19:05 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 19:05 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
But my word, it glitches a lot
----------------
Robert
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#72
10-25-2024, 06:33 PM
I guess you're in the UK (given the time diff)?
Can you please drop your php fle in a code block? I'll do the test again.
Find
the_bertrum Online
Senior Member+
*
Posts: 1,870
Threads: 43
Joined: Mar 2020
Reputation: 85
#73
10-25-2024, 06:47 PM
(10-25-2024, 06:33 PM)kurt1970 Wrote: I guess you're in the UK (given the time diff)?
Can you please drop your php fle in a code block? I'll do the test again.

Code:
#!/usr/bin/php
<?php
/*
* SPDX-License-Identifier: GPL-3.0-or-later
* Copyright 2014 The moOde audio player project / Tim Curtis
*/

require_once __DIR__ . '/../inc/common.php';
require_once __DIR__ . '/../inc/session.php';
require_once __DIR__ . '/../inc/sql.php';

if (isset($argv[1])) {
    $opt = explode(',', $argv[1]);
    $sleepInterval = $opt[0];
    $resumePlay = $opt[1];
    $threshold = $opt[2];
} else {
    $sleepInterval = 6;
    $resumePlay = 'Yes';
    $threshold = 3;
}
//workerLog('mpdmon.php: Options: ' . $sleepInterval . '|' . $resumePlay . '|' . $threshold);

$logMessage = 'alsa_output: Decoder is too slow; playing silence to avoid xrun';
$msgCount = 0;
$currentFile = '';
$logSize = filesize(MPD_LOG) - 1024;
session_id(phpSession('get_sessionid'));

while (true) {
    phpSession('open_ro'); // NOTE this does open/close so it must be in the loop to get latest session

    if ($currentFile != $_SESSION['currentfile']) {
        $msgCount = 0;
    }

    // Only radio stations that opt in for monotoring
    if (isset($_SESSION[$_SESSION['currentfile']]) && $_SESSION[$_SESSION['currentfile']]['monitor'] == 'Yes') {
        //workerLog('mpdmon: Monitoring: ' . $_SESSION['currentfile']);
        clearstatcache();
        $currentSize = filesize(MPD_LOG);
        $currentFile = $_SESSION['currentfile'];

        if ($logSize != $currentSize) {
            // Seek to last end position in log file
            $fh = fopen(MPD_LOG, "r");
            fseek($fh, $logSize);

            // Read log messages and check for match
            while ($data = fgets($fh)) {
                //workerLog($data);
                if (strpos($data, $logMessage) !== false) {
                    $msgCount++;
                    workerLog('mpdmon: ' .
                        'Buffer underrun ' . $msgCount . ' detected: ' .
                        $_SESSION[$_SESSION['currentfile']]['name']
                    );
                }

                if ($msgCount == $threshold) {
//                    $msg = 'mpdmon: MPD restarted';
//                    sysCmd('systemctl restart mpd');
                    $msg = 'mpdmon: MPD stopped';
                    sysCmd('mpc stop');
                    if ($resumePlay == 'Yes') {
                        $msg .= ', play resumed';
                        sysCmd('mpc play');
                    }
                    workerLog($msg);
                    $msgCount = 0;
                }
            }

            fclose($fh);
            $logSize = $currentSize;
        }
    }

    sleep($sleepInterval);
}
----------------
Robert
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#74
10-25-2024, 07:04 PM
Different here... Let me check on another instance...
Code:
moode@moode:~ $ tail -f  /var/log/mpd/log


Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:01 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:02 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#75
10-25-2024, 07:23 PM (This post was last modified: 10-25-2024, 07:26 PM by kurt1970.)
Ok. Seems to work on another instance. I set the "Message threshold"  to 1, and this seems to behave like your script.
Code:
Oct 25 21:21 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:21 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"


Oct 25 21:24 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 21:24 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"

Code:
20241025 210934 mpdmon: Buffer underrun 1 detected: Mother Earth Jazz
20241025 210934 mpdmon: Buffer underrun 2 detected: Mother Earth Jazz
20241025 210934 mpdmon: Buffer underrun 3 detected: Mother Earth Jazz
20241025 210934 mpdmon: MPD stopped, play resumed
20241025 210934 mpdmon: Buffer underrun 1 detected: Mother Earth Jazz
20241025 211431 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211437 mpdmon: Buffer underrun 2 detected: Super Stereo 7
20241025 211443 mpdmon: Buffer underrun 3 detected: Super Stereo 7
20241025 211443 mpdmon: MPD stopped, play resumed
20241025 211658 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211701 mpdmon: Buffer underrun 2 detected: Super Stereo 7
20241025 211707 mpdmon: Buffer underrun 3 detected: Super Stereo 7
20241025 211707 mpdmon: MPD stopped, play resumed
20241025 211723 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211723 mpdmon: MPD stopped, play resumed
20241025 211723 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211723 mpdmon: MPD stopped, play resumed
20241025 211723 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211723 mpdmon: MPD stopped, play resumed
20241025 211723 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211723 mpdmon: MPD stopped, play resumed
20241025 211723 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211723 mpdmon: MPD stopped, play resumed
20241025 211723 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 211723 mpdmon: MPD stopped, play resumed
20241025 212120 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 212120 mpdmon: MPD stopped, play resumed
20241025 212417 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 212417 mpdmon: MPD stopped, play resumed
20241025 212526 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241025 212526 mpdmon: MPD stopped, play resumed

Let me put a new image on my test instance, as it may be polluted. Stay tuned. Smile
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#76
10-25-2024, 08:11 PM
Hi @the_bertrum, I reimaged the instance, and so far your fix seems to do the job. I'll let it run for some time.


Code:
Oct 25 21:56 : player: played "SDCARD/Stereo Test/LRMonoPhase4.flac"
Oct 25 22:00 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 22:04 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 22:04 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 22:05 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 22:05 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 22:05 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 22:05 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 22:06 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 22:06 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 22:07 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 22:07 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Oct 25 22:08 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 25 22:08 : player: played "http://icecast.centaury.cl:7570/SuperStereoHiRes7"
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#77
10-26-2024, 01:55 AM
Hi @the_bertrum,
2 instances are playing with your modif in the php file since +6h without drops. Can you check with Tim how we can get this in moOde?
Tx,
Kurt
Find
the_bertrum Online
Senior Member+
*
Posts: 1,870
Threads: 43
Joined: Mar 2020
Reputation: 85
#78
10-26-2024, 06:15 AM
Well the only difference is that rather than restarting MPD, it simply stops playback. That was always enough to fix xrun conditions for me with my old script, and it seems the same approach works for me on that super7 stream, and has worked well for you too. It also helps avoid any conflict with other things that restart MPD. I'm sure Tim will evaluate these findings and decide if it makes sense to incorporate it officially. I don't know if there are other scenarios where an MPD restart is actually needed, so it might be impractical.

Thankfully, moOde is fully open, so if this doesn't make it into the official code, it is really quite trivial to make the change again after an upgrade.
----------------
Robert
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#79
10-26-2024, 06:48 AM (This post was last modified: 10-26-2024, 11:20 AM by kurt1970.)
Hi @the_bertrum. I do have xrun conditions on other stations as well, but much less frequent than on the Super Stereo stations, making the latter an ideal test case. I can perfectly live with glitches etc, but the difference with your fix is that the stream doesn't drop anymore, and this is a really nice improvement!

Let's hope @Tim Curtis takes this exercise and findings into consideration to adapt your approach in a next release.

Afterall, my intention is to help making moOde a better moOde for all of us. Last week I had a conversation with one of the founders of Gato Audio in Denmark (not your every day Walmart store). They didn't know moOde, but now they'll look into it. Always happy to contribute/test

BTW: Robert's fix keeps the music going. 0 drops since the last 16h. :-)

And yes, for those of you who do the math, I don't sleep that much. I used to do this as a baby Smile. Reality is that I work in an intl context, so at some point you get used to that, kind of... Smile

Cheers,
k
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#80
10-26-2024, 08:37 PM (This post was last modified: 10-26-2024, 10:33 PM by kurt1970.)
@Tim Curtis, Testing it in 9.1.4.

It recovered for a while, but after some time, it drops.

To get it working, I've to disable the stream monitor and put the script of @the_bertrum in place.

I looked at your code and saw the changes compared to 9.1.3. I see you restart mpd, while Robert stop/starts it. Could that explain the different behavior?

Code:
Oct 26 23:32 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 26 23:37 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 26 23:48 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 26 23:51 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 26 23:55 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Oct 26 23:58 : alsa_output: Decoder is too slow; playing silence to avoid xrun


Code:
Oct 26 23:55:01 moode systemd[1]: log2ram-daily.service: Deactivated successfully.
Oct 26 23:55:59 moode systemd[1]: mpd.service: Main process exited, code=killed, status=9/KILL
Oct 26 23:55:59 moode systemd[1]: mpd.service: Failed with result 'signal'.
Oct 26 23:55:59 moode systemd[1]: mpd.service: Consumed 4.640s CPU time.
Oct 26 23:55:59 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 26 23:55:59 moode dbus-daemon[487]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.tim>
Oct 26 23:55:59 moode systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Oct 26 23:56:00 moode dbus-daemon[487]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct 26 23:56:00 moode systemd[1]: Started systemd-timedated.service - Time & Date Service.
Oct 26 23:56:00 moode mpd[19257]: Ignoring the 'pid_file' setting in systemd mode
Oct 26 23:56:00 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 26 23:56:31 moode systemd[1]: systemd-timedated.service: Deactivated successfully.
Oct 26 23:59:00 moode systemd[1]: mpd.service: Main process exited, code=killed, status=9/KILL
Oct 26 23:59:00 moode systemd[1]: mpd.service: Failed with result 'signal'.
Oct 26 23:59:00 moode systemd[1]: mpd.service: Consumed 3.036s CPU time.
Oct 26 23:59:00 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 26 23:59:00 moode dbus-daemon[487]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.tim>
Oct 26 23:59:00 moode systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Oct 26 23:59:00 moode dbus-daemon[487]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct 26 23:59:00 moode systemd[1]: Started systemd-timedated.service - Time & Date Service.
Oct 26 23:59:00 moode mpd[19749]: Ignoring the 'pid_file' setting in systemd mode
Oct 26 23:59:01 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 26 23:59:01 moode CRON[19829]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Oct 26 23:59:01 moode CRON[19832]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 60 2)
Oct 26 23:59:01 moode CRON[19829]: pam_unix(cron:session): session closed for user root
Oct 26 23:59:31 moode systemd[1]: systemd-timedated.service: Deactivated successfully.
Oct 27 00:00:02 moode systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service...
Oct 27 00:00:02 moode systemd[1]: Starting sysstat-collect.service - system activity accounting tool...



Code:
20241026 222425 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 222425 mpdmon: MPD restarted, accepting connections, play resumed
20241026 223017 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 223017 mpdmon: MPD restarted, accepting connections, play resumed
20241026 223023 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 223024 mpdmon: MPD restarted, accepting connections, play resumed
20241026 223648 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 223649 mpdmon: MPD restarted, accepting connections, play resumed
20241026 224328 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 224329 mpdmon: MPD restarted, accepting connections, play resumed
20241026 224856 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 224857 mpdmon: MPD restarted, accepting connections, play resumed
20241026 225712 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 225713 mpdmon: MPD restarted, accepting connections, play resumed
20241026 225928 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 225928 mpdmon: MPD restarted, accepting connections, play resumed
20241026 225931 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 225932 mpdmon: MPD restarted, accepting connections, play resumed
20241026 230241 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 230242 mpdmon: MPD restarted, accepting connections, play resumed
20241026 230306 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 230306 mpdmon: MPD restarted, accepting connections, play resumed
20241026 230542 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 230543 mpdmon: MPD restarted, accepting connections, play resumed
20241026 231228 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 231229 mpdmon: MPD restarted, accepting connections, play resumed
20241026 231502 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 231503 mpdmon: MPD restarted, accepting connections, play resumed
20241026 231727 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 231728 mpdmon: MPD restarted, accepting connections, play resumed
20241026 232358 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 232359 mpdmon: MPD restarted, accepting connections, play resumed
20241026 233202 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 233202 mpdmon: MPD restarted, accepting connections, play resumed
20241026 233730 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 233730 mpdmon: MPD restarted, accepting connections, play resumed
20241026 234843 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 234843 mpdmon: MPD restarted, accepting connections, play resumed
20241026 235134 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 235135 mpdmon: MPD restarted, accepting connections, play resumed
20241026 235559 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 235600 mpdmon: MPD restarted, accepting connections, play resumed
20241026 235900 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241026 235901 mpdmon: MPD restarted, accepting connections, play resumed
Find
Thread Closed 


Forum Jump: