Audio stops; need help with error messages

[seamusdemora]

This is a repeat/revision of #700; after reading it again, I realized I complicated the question far too much. I've marked #700 as closed.

Here's what's happening: Occasionally, during playback using bluez-alsa, the audio output just stops as shown below.
I'd like to try to get a handle on the cause, and hopefully find a cure.

First, I am using a script named rainstorm originally supplied by @borine. I have modified it slightly, and I run it from cron (i.e. the root crontab instead of systemd) on my RPi Zero 2W system.

Here's the rainstorm script as currently used:

#!/bin/bash
# exec &>/dev/null              # suppress all output
/usr/bin/echo "$(date); starting /usr/local/bin/rainstorm"
for device in $(/usr/bin/bluetoothctl devices Paired | /usr/bin/sed -n 's/^Device \([^ ]*\).*$/\1/p')
do
        /usr/bin/echo "$(date); loop 1, /usr/local/bin/rainstorm"
        /usr/bin/bluealsa-cli list-pcms | grep 'a2dpsrc/sink$' && break
        if /usr/bin/bluetoothctl info "$device" | /usr/bin/grep -i 0000110b ; then
                /usr/bin/bluetoothctl connect "$device"
        fi
done
while true; do
        /usr/bin/echo "$(date); loop 2, /usr/local/bin/rainstorm"
#       /usr/bin/mpg123 -o alsa -a bluealsa --quiet --no-control --loop -1 /home/pi/rainstorm.mp3
        /usr/bin/mpg123 -o alsa -a bluealsa --no-control --loop -1 /home/pi/rainstorm.mp3
#       /usr/bin/grep -q -m 1 '^PCMAdded.*a2dp.*sink' <(/usr/bin/bluealsa-cli monitor)
        /usr/bin/grep -m 1 '^PCMAdded.*a2dp.*sink' <(/usr/bin/bluealsa-cli monitor)
done

And here's the job as entered in the root crontab:

# START before bedtime; from the root crontab:   1. stifle wifi, 2. start 'rainstorm'=>'mpg123'
0 3 * * * /usr/bin/nmcli radio wifi off
1 3 * * * /usr/local/bin/rainstorm >> /home/pi/rainstormlog.txt 2>&1 

# STOP the following morning:  1. kill rainstorm, 2. kill mpg123, 3. restore wifi
0 15 * * * /usr/bin/pkill rainstorm && /usr/bin/pkill mpg123 >> /home/pi/rainstormlog.txt 2>&1
1 15 * * * /usr/bin/nmcli radio wifi on

The playback stopped sometime during the night (well before the scheduled termination as shown in the crontab).

I looked at two logs for clues: journalctl and /home/pi/rainstormlog.txt

From journalctl:

journalctl -S yesterday | less

I used the following search terms: blue, alsa, rainstorm, mpg123. But journalctl turned up nothing "interesting"

From /home/pi/rainstormlog.txt, following is the complete log entry from April 30:

Tue 30 Apr 03:05:01 UTC 2024; loop 1, /usr/local/bin/rainstorm
        UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
Attempting to connect to DF:45:E9:00:BE:8B
[^AESC[0;93m^BCHG^AESC[0m^B] Device DF:45:E9:00:BE:8B Connected: yes
[^AESC[0;92m^BNEW^AESC[0m^B] Endpoint /org/bluez/hci0/dev_DF_45_E9_00_BE_8B/sep1
[^AESC[0;92m^BNEW^AESC[0m^B] Endpoint /org/bluez/hci0/dev_DF_45_E9_00_BE_8B/sep2
[^AESC[0;92m^BNEW^AESC[0m^B] Transport /org/bluez/hci0/dev_DF_45_E9_00_BE_8B/sep1/fd0
Connection successful
Tue 30 Apr 03:05:04 UTC 2024; loop 2, /usr/local/bin/rainstorm
High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
        version 1.31.2; written and copyright by Michael Hipp and others
        free software (LGPL) without any warranty but with best wishes

Directory: /home/pi/
Playing MPEG stream 1 of 1: rainstorm.mp3 ...

MPEG 1.0 L III cbr128 44100 j-s

[73:05] Decoding of rainstorm.mp3 finished.

Playing MPEG stream 1 of 1: rainstorm.mp3 ...

MPEG 1.0 L III cbr128 44100 j-s

[73:05] Decoding of rainstorm.mp3 finished.

Playing MPEG stream 1 of 1: rainstorm.mp3 ...

MPEG 1.0 L III cbr128 44100 j-s
ALSA lib pcm.c:8570:(snd_pcm_recover) underrun occurred

[73:05] Decoding of rainstorm.mp3 finished.

Playing MPEG stream 1 of 1: rainstorm.mp3 ...

MPEG 1.0 L III cbr128 44100 j-s
Terminated

mpg123: death by SIGTERM
[src/libout123/modules/alsa.c:write_alsa():242] error: Fatal problem with alsa output, error -19.
[src/libout123/libout123.c:out123_play():700] error: Error in writing audio, wrote only -1 of 2400 (Success?)!

[42:39] Decoding of rainstorm.mp3 finished.

You can see that an underrun occurred during the "third round" of playback, but I'm not sure that (underrun) is significant as it occurs occasionally without audio stopping.

However, the "wheels come off" in the 4th round of playback. Playback appears to start, but then gets a SIGTERM (from my cron job apparently!), which is followed by the error: Fatal problem with alsa output, error -19.

Any and all feedback is welcome - I don't have a clue, but I wonder if some additional logging by systemd might help??

[borine]

I used the following search terms: blue, alsa, rainstorm, mpg123. But journalctl turned up nothing "interesting"

As I said in one of your earlier posts, this does not appear to be an issue with bluealsa or mpg123 (nor the rainstorm script for that matter). Something else is happening in the system during the night which is causing playback to stop. That is why your search terms are revealing "nothing interesting". I would advise to find out what time the playback is stopping, then look through the system logs for whatever is happening around that time.

The underrun is unexpected - the pi zero2 is more than capable of playing a mp3 file from the sd card using the bluetooth SBC codec without breaking a sweat. So although mpg123 recovers the stream, perhaps whatever caused the underrun has also caused other more serious problems?

[seamusdemora]

Yes - I recall your saying that it seemed to be a system issue. That's why I shut off wifi just before beginning playback (and unmounting a network drive). It's rather difficult to pinpoint even an approximate time when playback stops as mpg123 seems to not care whether it's playback is going to the speaker or not :) I was hoping there might be something to be teased out of the bluealsa systemd unit, but I guess that's not the case. Oh well...

[arkq]

It's rather difficult to pinpoint even an approximate time when playback stops as mpg123 seems to not care whether it's playback is going to the speaker or not :)

Maybe you could try to log output from something like date && hciconfig every few seconds. This should show you the approximate point where your device is not transmitting Bluetooth data any more (if that's indeed that case).

[seamusdemora]

FWIW: https://raspberrypi.stackexchange.com/a/147707/83790
Hope this helps you guys, and thank you again for all the help you've provided me.