Volumio crashes while playing QOBUZ in Hi Res (24/192)

WhiteAngelDoubs · May 27, 2021, 8:42am

Hi there,

I am a rather recent user of AMAZING Volumio (Virtuoso) and I must say that I am a happy user so far.

Only thing is, when I play Hi Res tracks on QOBUZ, especially with 24/192 ones, my system becomes unstable, the sound starts stuttering and eventually the whole system crashes…

When this happens, even remote SSH is unresponsive so I cannot even restart my device properly. I have not tried putting a monitor and a keyboard to see if it would work locally. It would defy my purpose anyway.

Since it is pretty easy to reproduce, I enabled the live log but I must say, nothing relevant came up:

Starting Live Log…
command failed: Device or resource busy (-16)
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
wlan0: WPA: Group rekeying completed with b0:b2:8f:f9:c4:15 [GTK=CCMP]
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
pam_unix(sudo:session): session closed for user root
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
info: Listing playlists
info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::volumioGetVisibleSources
info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri
info: handleBrowseUri took 319 milliseconds
info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri
info: handleBrowseUri took 1125 milliseconds
info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri
info: handleBrowseUri took 771 milliseconds
info: CoreCommandRouter::volumioReplaceandPlayItems
info: CoreStateMachine::ClearQueue
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
info: CorePlayQueue::clearPlayQueue
info: CorePlayQueue::saveQueue
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushQueue
info: CoreStateMachine::addQueueItems
info: CorePlayQueue::addQueueItems
info: Adding Item to queue: qobuz://album/0886445517880
info: Exploding uri qobuz://album/0886445517880 in service qobuz
info: explodeUri took 397 milliseconds
info: CorePlayQueue::saveQueue
info: CoreCommandRouter::volumioPushQueue
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
info: CoreCommandRouter::volumioPlay
UNSET VOLATILE
info: CoreStateMachine::play index 0
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
info: CoreStateMachine::play index undefined
info: CoreStateMachine::setConsumeUpdateService undefined
info: CorePlayQueue::getTrack 0
info: CoreStateMachine::startPlaybackTimer
info: CorePlayQueue::getTrack 0
info: [1622022511958] ControllerQobuz::clearAddPlayTrack
info: getStreamUrl took 370 milliseconds

info: sendMpdCommand stop took 9 milliseconds

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: sendMpdCommand clear took 11 milliseconds

error: updateQueue error: null
info: ------------------------------ 23ms

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: sendMpdCommand add “http://streaming-qobuz-std.akamaized.net:80/file?uid=1607885&eid=27606061&fmt=27&profile=raw&app_id=539451548&cid=1006529&etsp=1622026112&hmac=b_oboAVOTqf_7TzbH3h1J3IeZb8” took 3 milliseconds
info: CoreStateMachine::setConsumeUpdateService mpd

info: ------------------------------ 9ms
info: sendMpdCommand play took 7 milliseconds
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

bcm2835-i2s fe203000.i2s: I2S SYNC error!
info:
---------------------------- MPD announces state update: player
info: sendMpdCommand status took 42 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 13 milliseconds
info: sendMpdCommand playlistinfo took 9 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus stop
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 88ms
info: sendMpdCommand playlistinfo took 102 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 138ms
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
info: Listing playlists
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::volumioGetVisibleSources
info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
info: CorePlayQueue::getTrack 0
info: CorePlayQueue::getTrack 1
info: Prefetching next song
info: [1622022850974] ControllerQobuz::prefetch
info: getStreamUrl took 340 milliseconds

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: sendMpdCommand add “http://streaming-qobuz-std.akamaized.net:80/file?uid=1607885&eid=27606062&fmt=27&profile=raw&app_id=539451548&cid=1006529&etsp=1622026451&hmac=j_ejE0HE9ZLaWmS_f530BVB0XtA” took 3 milliseconds
info: CoreStateMachine::setConsumeUpdateService mpd

info:
---------------------------- MPD announces state update: options
info: ------------------------------ 6ms
info: sendMpdCommand consume 1 took 3 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 8 milliseconds

info: sendMpdCommand playlistinfo took 17 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::startPlaybackTimer
info: CorePlayQueue::getTrack 1
info: CorePlayQueue::getTrack 1

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 68ms
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: ------------------------------ 5ms
info: sendMpdCommand status took 3 milliseconds

info: sendMpdCommand playlistinfo took 8 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 1

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 42ms
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
info: Listing playlists
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::volumioGetVisibleSources
info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
info: CoreCommandRouter::getUIConfigOnPlugin
info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus
info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
pam_unix(sudo:session): session closed for user root
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache
info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
pam_unix(sudo:session): session opened for user root by (uid=0)
info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
info: CoreCommandRouter::getUIConfigOnPlugin
info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus
info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
pam_unix(sudo:session): session closed for user root
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache
info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks
pam_unix(sudo:session): session closed for user root
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan
wlan0 Interface doesn’t support scanning : Device or resource busy
info: Cannot use regular scanning, forcing with ap-force
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
command failed: Device or resource busy (-16)
error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force
command failed: Device or resource busy (-16)
pam_unix(sudo:session): session closed for user root
error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan
wlan0 Failed to read scan data : Resource temporarily unavailable
info: Cannot use regular scanning, forcing with ap-force
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
command failed: Device or resource busy (-16)
error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force
command failed: Device or resource busy (-16)
info: CoreCommandRouter::volumioPause
info: CoreStateMachine::pause
info: CoreStateMachine::stPlaybackTimer
info: CoreStateMachine::servicePause
info: CorePlayQueue::getTrack 1
info: CoreCommandRouter::servicePause
info: [1622023014889] ControllerQobuz::pause
info: CoreStateMachine::setConsumeUpdateService mpd
info: ControllerMpd::pause

info:
---------------------------- MPD announces state update: player
info: sendMpdCommand pause took 29 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 2 milliseconds

info: sendMpdCommand playlistinfo took 22 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 1

info: CoreStateMachine::syncState stateService pause
info: CoreStateMachine::syncState currentStatus pause
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::stPlaybackTimer
info: ------------------------------ 46ms

So I had to downgrade the Sound quality to FLAC Hi-Res 24 bit up to 96 kHz to keep the problem contained.

My internet BW is approximatly 8 Mbps and is rather stable.
I use a Netgear A6210 USB WiFi Adapter that stays operational (from my router’s pov) even after the crash happened. I doubt the network stability in general is the problem as te problem reproduces with a 1 Gbit/s wired Ethernet connection.

Is it a known issue from Volumio’s dev team?

Does anyone run into this already? Is there a fix/workaround?

Thank you for the support!

Volumio Information

Volumio Version: 2.882
Hardware: Raspberry 4 Model B (underclocked from 1.6 Ghz to 800 Mhz)
DAC: HiFiBerry Digi+ Pro

Wheaten · May 27, 2021, 9:49am

can you give some examples (tracks) that causes this issue , so I can see if I can reproduce it?

WhiteAngelDoubs · May 27, 2021, 10:59am

I usually reproduce this while listening to Jeff Buckley - Grace album (whatever the track). It does not happen right away or without a push. What I did to speed things up, I started browsing in and out of every menu from the setting section while playing the album and all of the sudden, it freezes and the API as well as the remote SSH are unresponsive. It works for other album like Aerosmith - The greatest hits, The Doobie Brothers - The Best of The Doobies, Guns N’ Roses - Appetite for Destruction, etc. If I just play them without messing too much with the UI, it is stable-ish. Also, playing with the player controls (Next track/Previous track) “erratically” can help.

May I say that I also changed the default buffering setup to 4MB/20% and before it was 8MB/30%.

So far, this is all I can think of…

Wheaten · May 27, 2021, 11:27am

Then I will test it with Guns n’ Roses

Wheaten · May 27, 2021, 11:50am

Just ran some test with Volumio 2.904.
Took Guns n’ Roses Appetite for Destruction (Super Deluxe)

Abusing the player controls, makes Volumio confuse. That part I have reported before.
But I am unable to duplicate the stuttering. Worked my way through menus, even started a library scan with 60.000 tracks. But it keeps playing. I do notice sometimes unresponsive behavior for 30 seconds.

Wheaten · May 27, 2021, 11:55am

and just now, I saw the UI with the loading icon popping up. However no interruption in audio output.

WhiteAngelDoubs · May 27, 2021, 11:58am

Well, I am not sure this is the same problem… In my case everything freezes indefinitely. WHat is your network BW? Mine being a tad weak…

Wheaten · May 27, 2021, 12:00pm

And for the next question, IE speed is 280Mb/s

WhiteAngelDoubs · May 27, 2021, 1:06pm

OK so you have a similar Wifi BW but a far better internet connection… So it might be where the bottleneck is. However, is it still acceptable that it crashes when we run out of BW?

Wheaten · May 27, 2021, 3:05pm

Well suppose you stream with 3000kbps you need 3MB bandwidth. I think even the worst ISP starts of with 5.

WhiteAngelDoubs · May 27, 2021, 4:45pm

On my PC, I usually download most files at ~800 kB/s. This is way passed 5 Mbps (I assumed you meant 5Mb not 5MB by the way). I do not think the CPU load is an issue, that is something I monitored closely when I was looking for the sweet underclocking spot So what else could it be then?

Wheaten · May 28, 2021, 7:39am

Do you have the same issues, when you run the rPi on normal speed? As I see you underclocked it.

WhiteAngelDoubs · May 28, 2021, 7:56am

Hey @Wheaten (Will? )!

Yesterday I eventually snapped! I ripped the SD card off the raspi, flashed the whole system all over again, and did things differently this time:

No Underclocking (userconfig.cfg), instead I changed the governor configuration from performance to ondemand (I did not know until today I could do that) and it fits the bill (keeping the temperature on the down low) for me so far…
I installed the wifi driver using the install-wifi script developed by MrEngman instead of using the one provided by volumio (can’t remember the repo though)
I kept the audio quality to Highest Possible (not that I think it has any influence on my problem, I would even bet on the contrary)

So far, it still randomly stutters on Hi Res files, the audio stops sometime but the UI stays responsive, so it is manageable. This never happens when using 44.1/16 or 24/96. Why is it so unstable with 24/192 formats?

Overall, if I do not mess with the UI, I can play anything (with a few stutterings still). I hope this can be improved someday… My Raspi is more powerful than any other raspi on which Volumio runs perfectly fine, so I do not think the cpu power plays any role here.

Bottom line, does not crash anymore (for now) .

I will keep monitoring it and will keep you posted either way.

Thanks for the support.

Wheaten · May 28, 2021, 10:15am

I still would see the same test without any manipulation on processor speed. If I am correct under/over clocking is not official supported on the rPi4. You can manipulate the CPU, GPU and SDRAM Voltage, in the config.txt, but this might also result in unstable behavior, as Wi-Fi, network, PLL’s need a certain frequency to operate.

WhiteAngelDoubs · May 28, 2021, 10:59am

Is that so? What about the modification I did on the governor? Should I expect trouble?

Wheaten · May 28, 2021, 1:09pm

Don’t know.
But you have an issue which I can’t duplicate or reproduce. The only way to narrow such errors down, is starting from a clean system, without any tweaking, plugins etc.
Only when this fresh start run stable, then you can start tweaking step by step.
Without the bare basic, it’s impossible to support.

WhiteAngelDoubs · May 28, 2021, 2:21pm

That is more or less what I did. The only tweak I did is to enable the ondemand governor thing. If it starts going sideways again, I will fall back on performance mode.

WhiteAngelDoubs · May 29, 2021, 11:53am

Hey @Wheaten,

I pinpointed the problem. No relation with my tweaking, this is just the Wi-Fi adapter driver that is unstable…

Wheaten · May 29, 2021, 12:00pm

You don’t have a switch or accesspoint that has IGMP Snooping active. Seems to causes issues when streaming?

If not back to copper?

WhiteAngelDoubs · May 29, 2021, 10:16pm

Well @Wheaten, not sure if my setup does this. I have the router provided by my carrier and I guess it uses the IGMP thingy to segregate the TV from normal internet tragic but I doubt this is a problem. My pi is very stable as long as I do not use the wifi USB adapter. So in conclusion, I bought a fancy adapter for nothing… The very reason I bought it is because with the on-board adapter the qos is crap.
Anyway, I think I will have to wait for volumio to rebase on buster, maybe then, who knows…

For now I guess case is close. Thanks.