[he is back] UI down when getting to the end of the playlist, while using bluetooth

[Maitresinh]

This is the sequel of classified but unsolved case.
(http://moodeaudio.org/forum/showthread.php?tid=2099)

As i have new leads, i think it can be of interest.And hopefully, eventually resolved.

To summarize

I use a PI3B+ with a DIGIamp DAC to listen music from my NAS (and old Dlink DNS320).
Everything is fine when i'm using the DAC to send the music to speakers.

But, when i'm using bluetooth (out, to send music to a bluetooth speaker), the front-end become eventually unavaialble (but no moode via SSH).

So, here are the news

1- I've bought and try a 19V power supply. Nothing have changed.
2- I've noticed that there is no problem with bluetooth while i'l listening to radio. So it may be a NAS problem
3- thus, i've updated the NAS with the "last" (2014) Firware, to get a more recent version of Samba. Nothing have changed 
4- However, there is here a non official firware. Maybe it's worth trying ? (https://sites.google.com/site/altfirmware/)
5- Last but not least, i've noticed a strange thing : usually the "freeze" happens when i reach the end of an album. So i've start an album, jumped to the last song, and listened the last few second. When it came to the end, the "freeze" happened. Just in that moment. Is that help ? (logs below)

---------------------
pi@moode:~ $ egrep -i '(warn|error|fail)' /var/log/syslog
Jan 29 00:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 01:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 02:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 03:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 04:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 05:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 06:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 07:12:51 moode rngd[340]: stats: FIPS 140-2 failures: 0
Jan 29 07:29:08 moode bluetoothd[1112]: Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply
Jan 29 07:30:36 moode bluealsa[1135]: /usr/bin/bluealsa: Couldn't release transport: GDBus.Error:org.freedesktop.DBus.Error.UnknownObject: Method "Release" with signature "" on interface "org.bluez.MediaTransport1" doesn't exist
Jan 29 07:30:36 moode systemd[1]: mpd.service: Failed with result 'timeout'.
Jan 29 07:30:37 moode bluealsa[1135]: /usr/bin/bluealsa: Couldn't release transport: GDBus.Error:org.freedesktop.DBus.Error.UnknownObject: Method "Release" with signature "" on interface "org.bluez.MediaTransport1" doesn't exist
Jan 29 07:14:13 moode kernel: [    0.739112] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = bad04000 dma = 0xfad04000 len=9024
Jan 29 07:14:13 moode kernel: [    0.750874] WARN::hcd_init_fiq:457: FIQ on core 1
Jan 29 07:14:13 moode kernel: [    0.752445] WARN::hcd_init_fiq:458: FIQ ASM at 8067e4c4 length 36
Jan 29 07:14:13 moode kernel: [    0.753978] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
Jan 29 07:14:13 moode kernel: [    4.593593] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 07:14:13 moode kernel: [    4.689895] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 07:14:13 moode kernel: [    4.698322] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 07:14:13 moode kernel: [    4.717661] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 07:14:13 moode kernel: [    4.822893] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 07:14:13 moode kernel: [    7.716397] random: 7 urandom warning(s) missed due to ratelimiting
Jan 29 07:14:38 moode bluetoothd[1113]: Failed to set privacy: Rejected (0x0b)
Jan 29 07:14:40 moode kernel: [   34.403187] CIFS VFS: server 192.168.0.11 of type Samba 3.2.8 returned unexpected error on SMB posix open, disabling posix open support. Check if server update available.
Jan 29 08:47:45 moode kernel: [    0.739000] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = bad04000 dma = 0xfad04000 len=9024
Jan 29 08:47:45 moode kernel: [    0.750775] WARN::hcd_init_fiq:457: FIQ on core 1
Jan 29 08:47:45 moode kernel: [    0.752349] WARN::hcd_init_fiq:458: FIQ ASM at 8067e4c4 length 36
Jan 29 08:47:45 moode kernel: [    0.753886] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
Jan 29 08:47:45 moode kernel: [    4.692632] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 08:47:45 moode kernel: [    4.891150] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 08:47:45 moode kernel: [    4.891154] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 08:47:45 moode kernel: [    4.918859] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 08:47:45 moode kernel: [    4.952334] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 08:47:45 moode kernel: [    4.954149] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 08:47:45 moode kernel: [    7.908851] random: 7 urandom warning(s) missed due to ratelimiting
Jan 29 08:48:09 moode bluetoothd[1110]: Failed to set privacy: Rejected (0x0b)
Jan 29 08:48:11 moode kernel: [   34.191756] CIFS VFS: server 192.168.0.11 of type Samba 3.2.8 returned unexpected error on SMB posix open, disabling posix open support. Check if server update available.
Jan 29 09:51:59 moode rngd[339]: stats: FIPS 140-2 failures: 0
Jan 29 10:34:23 moode kernel: [    0.738880] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = bad04000 dma = 0xfad04000 len=9024
Jan 29 10:34:23 moode kernel: [    0.750656] WARN::hcd_init_fiq:457: FIQ on core 1
Jan 29 10:34:23 moode kernel: [    0.752230] WARN::hcd_init_fiq:458: FIQ ASM at 8067e4c4 length 36
Jan 29 10:34:23 moode kernel: [    0.753766] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
Jan 29 10:34:23 moode kernel: [    4.567376] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 10:34:23 moode kernel: [    4.697560] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 10:34:23 moode kernel: [    4.710720] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 10:34:23 moode kernel: [    4.729019] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 10:34:23 moode kernel: [    4.800190] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 10:34:23 moode kernel: [    4.815540] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Jan 29 10:34:23 moode kernel: [    7.537216] random: 7 urandom warning(s) missed due to ratelimiting
Jan 29 15:40:48 moode bluetoothd[1163]: Failed to set privacy: Rejected (0x0b)
Jan 29 15:40:53 moode kernel: [   45.117944] CIFS VFS: server 192.168.0.11 of type Samba 3.2.8 returned unexpected error on SMB posix open, disabling posix open support. Check if server update available.
Jan 29 16:40:15 moode rngd[328]: stats: FIPS 140-2 failures: 0

[TheOldPresbyope]

1. So, you have Bluez-alsa errors which I've never experienced. A little search-engine work turns up hits which suggest perhaps your Bluetooth speaker is powering off during playback. I can't say more. Maybe the Bluez-alsa maintainer can. 

As two datapoints, In a first test, I ran a moOde 6.4.1 player for 48 hours straight using a radio station as input and a powered Bluetooth speaker as output. In the current second test, it's been running for hours straight with my NAS as input and the same BT speaker as output. No errors. 

2. That final syslog message

Code:

Jan 29 15:40:53 moode kernel: [   45.117944] CIFS VFS: server 192.168.0.11 of type Samba 3.2.8 returned unexpected error on SMB posix open, disabling posix open support. Check if server update available.

suggests your server is still behind the curve. In my case, my OpenMediaVault NAS is running Samba Version 4.5.16-Debian, compared to moOde running Samba Version 4.9.5-Debian. OTOH, I don't know if the old version is a contributing problem and I can't help further if it is.

Sorry, but I don't know what more to contribute to this discussion.

Regards,
Kent

[vinnn]

It sounds to me that your Bluetooth speaker is doing something funky which is causing the Bluetooth adapter module to hang/crash or causing bluez-alsa to hang which in turn causes mpd to hang which stops the web interface from responding because it/nginx can't get status updates from mpd.
As you state that a constant audio stream like radio is OK it is most likely that the speaker is not handling the break between streams of individual tracks well and the potential changes in sample rate between streams which is locking up the sending process. Maybe increasing the audio buffer in the mpd config screen might help, to something like 20MB (20480 KB), maybe not.

The range isn't great with the Pi's Bluetooth adapter so that might be a contributing factor but ultimately this sounds like the root cause is a hardware problem not software, primarily the thing you're streaming to.
Maybe you can get a better idea by inspecting the kernel logs as it happens, e.g. replicate the issue whilst running;

Code:

sudo journalctl -kef

...or run 'dmesg' after the event.

If you get nothing there then the Pi's Bluetooth adapter is probably fine and you'd go on to do the same with the system journal. You could also make bluetoothd output log debug messages by editing the systemd unit file, e.g;

Code:

sudo nano /lib/systemd/system/bluetoothd.service

... and change

Code:

ExecStart=/usr/sbin/bluetoothd --noplugin=sap

... to...

Code:

ExecStart=/usr/sbin/bluetoothd -d --noplugin=sap

... and restart bluetoothd or reboot.

Then replicate the issue whilst running..

Code:

sudo journalctl -ef

.. or give up on this Bluetooth speaker you're using for something better.

[Maitresinh]

Thanks for your friendly feedback (whatever i resolve the problem or not).

@vinn just to be sure, regarding the "sudo journalctl -kef" thing, i would have to

1/ start running in bluetooth
2/ open a ssh session and enter "sudo journalctl -kef"
3/ Wait for the "event" (freeze) and then ? post the result ?

It is the same runing "dmesg" after the event ?

However, it's unlikely to be the bluetooth speaker, as i've been testing with another bluetooth device, and it's the same. Plus, the problem seems to happen only when reaching the end of an album WHILE using bluetooth.

[TheOldPresbyope]

Hold the phone!

I just had what may be the same Bluetooth failure after several hours of continuous playback of tracks from NAS to Bluetooth speaker. This with the same system which had played a radio station for 48 hours straight:

RPi3A+
moOde 6.4.1
onboard BT adapter
JBL Flip2 (with external 5v power)
OpenMediaVault NAS with SMB shares

I've just spun up an RPi4B system to replicate the problem.

I'm on my way out the door for a doctor's appointment. Will open a new thread with the specifics later this afternoon.

Regards,
Kent

[vinnn]

@vinn just to be sure, regarding the "sudo journalctl -kef" thing, i would have to

1/ start running in bluetooth
2/ open a ssh session and enter "sudo journalctl -kef"
3/ Wait for the "event" (freeze) and then ? post the result ?

Yes, I'm not necessarily saying post all your logs here as it's unlikely to be an issue relating to the Moode project, just giving you some assistance on where to find more verbose information.

The log you posted suggests at least some hardware related thing is causing this...

Code:

Jan 29 07:29:08 moode bluetoothd[1112]: Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply
Jan 29 07:30:36 moode bluealsa[1135]: /usr/bin/bluealsa: Couldn't release transport: GDBus.Error:org.freedesktop.DBus.Error.UnknownObject: Method "Release" with signature "" on interface "org.bluez.MediaTransport1" doesn't exist
Jan 29 07:30:36 moode systemd[1]: mpd.service: Failed with result 'timeout'.
Jan 29 07:30:37 moode bluealsa[1135]: /usr/bin/bluealsa: Couldn't release transport: GDBus.Error:org.freedesktop.DBus.Error.UnknownObject: Method "Release" with signature "" on interface "org.bluez.MediaTransport1" doesn't exist

The bluetooth endpoint errored (line 1), which made bluealsa hang ("Couldn't release transport" line 2) which made mpd hang/stop responding/fail (line 3) which would make the web interface hang too.

How far away is this bluetooth speaker away from the Pi?
What kind of case is fitted to the Pi?

[Maitresinh]

@TheOldPresbyope Great ! Please to hear i'm not the only one wiht this bug. Any news ?

@vinnn i've tried before with the bluetooth speaker at the first floor (and Pi in the ground floor), and now i'm less than 1 meter away. Same thing. Same thing also with a bluetooth headphone: when listening to music on a NAS, at the end of an album (ie : when the last track is other), the Ui is down. It seems that if i do not listen the entire album, it keeps working.

[CallMeMike]

@TheOldPresbyope Great ! Please to hear i'm not the only one wiht this bug. Any news ?
................. snip ..............................

As per @OldPresbyope statement in his last entry here << I'm on my way out the door for a doctor's appointment. Will open a new thread with the specifics later this afternoon >> he has actually done so:  http://moodeaudio.org/forum/showthread.php?tid=2140

[vinnn]

@TheOldPresbyope Great ! Please to hear i'm not the only one wiht this bug. Any news ?

@vinnn i've tried before with the bluetooth speaker at the first floor (and Pi in the ground floor), and now i'm less than 1 meter away. Same thing. Same thing also with a bluetooth headphone: when listening to music on a NAS, at the end of an album (ie : when the last track is other), the Ui is down. It seems that if i do not listen the entire album, it keeps working.

I actually replied to this but somehow did it in the completely wrong thread mixed up with another issue! What an idiot
So now I'm in the right thread...


Was doing a bit of work in the garden so I took out my Jam Heavy Metal bluetooth speaker and played several albums over bluetooth from my Pi3 running Moode 6.4.1, haven't actually used Moode for this before but it works great.
The listening room/den backs onto the garden so the speaker was about 4 meters away from the Pi max, my Pi is in a metal case so that may also effect potential range but had no issues/dropouts today.
I made a point not to make a big queue of multiple albums but played an album, let it run out, stuck on another and so on so there's several minutes of idle time between each. Six albums in, no problems.

Also tested switching off the Jam Heavy Metal whilst Moode was playing a couple of times, again no problem. I was able to switch the speaker back on and hit play in Moode and the music resumed.

System info whilst connected to bluetooth...

Code:

S Y S T E M   P A R A M E T E R S

moOde release        = 6.4.1 2020-01-23
Raspbian OS        = 10.2
Linux kernel        = 4.19.83-v7+ #1277
Platform        = Pi-3B 1GB v1.2
Architecture        = armv7l (32-bit)
System uptime        = up 3 hours, 29 minutes
Timezone        = Europe/London
Current time        = 2020-02-02 15:22:39

Host name        = Hi-Fi
Ethernet address    = 192.168.1.99
Ethernet MAC        = b8:27:eb:f5:be:0e
WLAN address        = unassigned
WLAN MAC        = no adapter
WLAN country        = US

SoC identifier        = bcm2837
Core count        = 4
Kernel timer freq    = 100 Hz
SDCard freq        = 50 MHz
USB boot        = not enabled
Warranty        = OK

Root size        = 15G
Root used        = 22%
Root available        = 11G
Root expand        = expanded
Memory free        = 127 MB
Memory used        = 157 MB
SoC temperature        = 46.2°C

CPU governor        = performance
Onboard WiFi        = Off
Onboard BT        = On
HDMI output        = Off
Eth addr wait        = On
Max USB current        = Off
USB (UAC2) fix        = Off
Pi-3B+ eth fix        = Off
SSH term server        = On

PHP-FPM version        = 7.3.11
NGINX version        = 1.14.2
SQLite3 version        = 3.27.2
Hostapd version        = 2.8-devel
WiringPi version    = 2.50
RPi.GPIO version    = 0.7.0

A U D I O   P A R A M E T E R S

Audio device        = USB audio device
Interface        = USB
Mixer name        = D50s
Hardware volume        = Controller detected
Max ALSA volume        = 100
Audio source        = Local
Output device        = Bluetooth
Resume MPD        = No
Volume knob        = 7
Volume mute        = Unmuted
Saved MPD vol        = 0
Preamp volume        = 0
ALSA version        = 1.1.8-1+rpt1
SoX version        = 0.1.2-3

Bluetooth controller    = On
Pairing agent        = Off
Airplay receiver    = On
Spotify receiver    = On
Squeezelite        = Off
UPnP client        = On
DLNA server        = On
GPIO button handler    = Off
UPnP browser        = Off

Auto-shuffle        = Off
Autoplay        = Off
Rotary encoder        = Off
Encoder params        = 100 2 3 23 24
Polarity inversion    = Off
Crossfeed        = Off
Crossfade        = Off
Parametric EQ        = Off
Graphic EQ        = Off
MPD httpd        = On

A P P E A R A N C E   S E T T I N G S

Theme            = Pure Black
Accent color        = River
Alpha blend        = 1.00
Adaptive background    = No
Background image    = No
Cover backdrop        = No
Cover blur        = 20px
Cover scale        = 1.25
CoverView auto-display    = Never
CoverView style        = Animated
Auto-shuffle filter    = None
Extra metadata        = Yes
Playback history    = Yes

L I B R A R Y   S E T T I N G S

Instant play action    = Clear/Play
Show genres column    = Yes
Album grouping        = by Album
Compilation identifier    = Various Artists
Recently added        = 1 Month
Ignore articles        = a,an,the
UTF8 character filter    = No
Hi-res thumbs        = Auto
Cover search pri    = Cover image file
Pixel ratio        = 1

M P D   S E T T I N G S

Version            = 0.21.16
Volume control        = software
ALSA device        = hw:1
SoX resampling        = disabled
SoX quality        = very high
SoX multithreading    = off
DSD over PCM (DoP)    = no
Replaygain        = off
Replaygain preamp    = 0
Volume normalization    = No
Audio buffer        = 20480 (kb)
Output buffer size    = 131072 (kb)

B L U E T O O T H   S E T T I N G S

Bluetooth ver        = 5.50
Bluealsa ver        = 2.0.0
Speaker sharing        = No
Resume MPD        = No
PCM buffer time        = 40000 (µs)

A I R P L A Y   S E T T I N G S

Version            = 3.3.5
Friendly name        = Moode Airplay
ALSA device        = hw:1
Interpolation        = soxr
Output bit depth    = S16
Output sample rate    = 44100
Session interruption    = no
Session timeout        = 120 (ms)
Latency offset        = 0.0 (secs)
Audio buffer        = 0.2 (secs)
Resume MPD        = No

S P O T I F Y   S E T T I N G S

Friendly name        = Moode Spotify
ALSA device        = plughw:1
Bit rate        = 320
Initial volume        = 0
Volume curve        = Logarithmic
Volume normalization    = No
Normalization pregain    = 0
Resume MPD        = No

S Q U E E Z E L I T E   S E T T I N G S

Version            = 1.8.7-1052 "DSD/SRC enabled"
Friendly name        = Moode
ALSA device        = hw:0
ALSA params        = 80:4::1
Output buffers        = 40000:100000
Task priority        = 45
Codec list        = flac,pcm,mp3,ogg,aac,alac,dsd
Other options        = -W -D 500 -R E -S /var/local
Resume MPD        = No

L O C A L   D I S P L A Y   S E T T I N G S

Local UI display    = Off
Mouse cursor        = On
Screen blank        = 600 Secs
Wake display on play    = Off
Brightness        = 255
Pixel aspect ratio    = Default
Rotate screen        = 0 Deg

... I couldn't reproduce your issue.

[Maitresinh]

damned. I am.
i think i will try to change my nas. That's the only thing i see.