Allo USBridge - Dropouts when playing Tidal

Transport: Allo USBridge
DAC: Schiit Yggdrasil
OS: Volumio (newest available at the time of writing)
Source file: Tidal playing via Volumio’s native integration

Every once in a while a dropout occurs. Music either stops completely (it shows as playing in Volumio GUI but there’s only silence) or there are a second long pauses. Issue occurs at random however I’ve noticed that on some tracks it occurs 100% of the time. Example track: https://tidal.com/track/94760828.

Issue did not occur on RaspberryPi (also running Volumio).

Journalctl and demsg output attached. If you need any other logs please tell me which and I’ll collect them for you.

[spoiler]Feb 01 19:15:11 volumio sudo[1947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Feb 01 19:15:11 volumio sudo[1947]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:11 volumio sudo[1947]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:11 volumio sudo[1949]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:11 volumio sudo[1949]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:11 volumio sudo[1949]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::volumioGetBrowseSources
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::volumioGetState
Feb 01 19:15:12 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Feb 01 19:15:12 volumio sudo[1957]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:12 volumio sudo[1957]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:12 volumio sudo[1957]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Feb 01 19:15:12 volumio sudo[1964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:12 volumio sudo[1964]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:12 volumio volumio[743]: info: Listing playlists
Feb 01 19:15:12 volumio sudo[1964]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:13 volumio volumio[743]: info: CoreCommandRouter::volumioGetQueue
Feb 01 19:15:13 volumio volumio[743]: info: CoreStateMachine::getQueue
Feb 01 19:15:13 volumio volumio[743]: info: CorePlayQueue::getQueue
Feb 01 19:15:14 volumio volumio[743]: info: No input data
Feb 01 19:15:14 volumio volumio[743]: info: No input data
Feb 01 19:15:15 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:21 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:22 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:22 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:28 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:32 volumio volumio[743]: info: CoreCommandRouter::volumioAddQueueItems
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::addQueueItems
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::addQueueItems
Feb 01 19:15:32 volumio volumio[743]: info: Adding Item to queue: tidal://song/100794834
Feb 01 19:15:32 volumio volumio[743]: info: Exploding uri tidal://song/100794834 in service streaming_services
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::saveQueue
Feb 01 19:15:32 volumio volumio[743]: info: CoreCommandRouter::volumioPushQueue
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::updateTrackBlock
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::getTrackBlock
Feb 01 19:15:32 volumio volumio[743]: info: CoreCommandRouter::volumioPlay
Feb 01 19:15:32 volumio volumio[743]: UNSET VOLATILE
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::play index 6
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService undefined
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::stop
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService undefined
Feb 01 19:15:32 volumio volumio[743]: UNSET VOLATILE
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::play index undefined
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService undefined
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::startPlaybackTimer
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:32 volumio volumio[743]: info: [1549048532974] streamingServices::clearAddPlayTrack
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand stop
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand clear
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces system playlist update
Feb 01 19:15:33 volumio volumio[743]: info: Ignoring MPD Status Update
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand load "http://ab-pr-ak.audio.tidal.com/a97c414
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: info: ------------------------------ 9ms
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand add "http://ab-pr-ak.audio.tidal.com/a97c4149
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces system playlist update
Feb 01 19:15:33 volumio volumio[743]: info: Ignoring MPD Status Update
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService mpd
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand play
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: ------------------------------ 10ms
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces state update: player
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::getState
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand status
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Feb 01 19:15:33 volumio kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::parseState
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand playlistinfo
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces state update: player
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::getState
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand status
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::parseTrackInfo
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::pushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreCommandRouter::servicePushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::syncState
Feb 01 19:15:33 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:33 volumio volumio[743]: info: STATE SERVICE {“status”:“play”,“position”:0,“seek”:0,“duration”:218,"sample
Feb 01 19:15:33 volumio volumio[743]: info: CURRENT POSITION 6
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::syncState stateService play
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::syncState currentStatus stop
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:33 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:15:33 volumio volumio[743]: info: ------------------------------ 110ms
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::parseState
Feb 01 19:15:33 volumio sudo[1997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:33 volumio sudo[1997]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand playlistinfo
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:15:34 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:15:34 volumio sudo[1997]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:34 volumio volumio[743]: info: parsing response…
Feb 01 19:15:34 volumio volumio[743]: info: ControllerMpd::parseTrackInfo
Feb 01 19:15:34 volumio volumio[743]: info: ControllerMpd::pushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::servicePushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::syncState
Feb 01 19:15:34 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:34 volumio volumio[743]: info: STATE SERVICE {“status”:“play”,“position”:0,“seek”:464,“duration”:218,“samp
Feb 01 19:15:34 volumio volumio[743]: info: CURRENT POSITION 6
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::syncState stateService play
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::syncState currentStatus play
Feb 01 19:15:34 volumio volumio[743]: info: Received an update from plugin. extracting info from payload
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:15:34 volumio sudo[2004]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:34 volumio sudo[2004]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:34 volumio volumio[743]: info: ------------------------------ 308ms
Feb 01 19:15:34 volumio sudo[2007]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:34 volumio sudo[2004]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:34 volumio sudo[2007]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:34 volumio sudo[2007]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:34 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:15:34 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:17:12 volumio systemd[1]: Starting Cleanup of Temporary Directories…
Feb 01 19:17:12 volumio systemd[1]: Started Cleanup of Temporary Directories.
Feb 01 19:17:55 volumio kernel: atc260x-rtc atc2603c-rtc.0: atc260x_rtc_settime(): 2019-02-01 19:17:55
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::volumioPause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::pause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::stPlaybackTimer
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::servicePause
Feb 01 19:19:05 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::servicePause
Feb 01 19:19:05 volumio volumio[743]: info: [1549048745864] streamingServices::pause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService mpd
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::pause
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::sendMpdCommand pause
Feb 01 19:19:05 volumio volumio[743]: info: sending command…
Feb 01 19:19:05 volumio volumio[743]: info: parsing response…
Feb 01 19:19:05 volumio volumio[743]: info:
Feb 01 19:19:05 volumio volumio[743]: ---------------------------- MPD announces state update: player
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::getState
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::sendMpdCommand status
Feb 01 19:19:05 volumio volumio[743]: info: sending command…
Feb 01 19:19:05 volumio volumio[743]: info: parsing response…
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::parseState
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::sendMpdCommand playlistinfo
Feb 01 19:19:05 volumio volumio[743]: info: sending command…
Feb 01 19:19:05 volumio volumio[743]: info: parsing response…
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::parseTrackInfo
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::pushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::servicePushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::syncState
Feb 01 19:19:05 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:19:05 volumio volumio[743]: info: STATE SERVICE {“status”:“pause”,“position”:0,“seek”:195953,“duration”:218,”
Feb 01 19:19:05 volumio volumio[743]: info: CURRENT POSITION 6
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::syncState stateService pause
Feb 01 19:19:05 volumio kernel: aotg_hub_endpoint_disable
Feb 01 19:19:05 volumio kernel: aotg_hcd aotg_hcd.1: ep5 index 1 from ep [out]
Feb 01 19:19:05 volumio kernel: aotg_hub_endpoint_disable
Feb 01 19:19:05 volumio kernel: aotg_hcd aotg_hcd.1: ep5 index 4 from ep [in]
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::syncState currentStatus pause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::stPlaybackTimer
Feb 01 19:19:05 volumio volumio[743]: info: ------------------------------ 58ms
Feb 01 19:19:05 volumio sudo[2245]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:19:05 volumio sudo[2245]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:19:05 volumio sudo[2245]: pam_unix(sudo:session): session closed for user root
Feb 01 19:19:05 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:19:05 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:19:12 volumio sshd[2255]: Accepted password for volumio from 192.168.0.13 port 44274 ssh2
Feb 01 19:19:12 volumio sshd[2255]: pam_unix(sshd:session): session opened for user volumio by (uid=0)
Feb 01 19:19:12 volumio systemd[1]: Starting user-1000.slice.
Feb 01 19:19:12 volumio systemd[1]: Created slice user-1000.slice.
Feb 01 19:19:12 volumio systemd[1]: Starting User Manager for UID 1000…
Feb 01 19:19:12 volumio systemd[1]: Starting Session 2 of user volumio.
Feb 01 19:19:12 volumio systemd-logind[516]: New session 2 of user volumio.
Feb 01 19:19:12 volumio systemd[1]: Started Session 2 of user volumio.
Feb 01 19:19:12 volumio systemd[2260]: pam_unix(systemd-user:session): session opened for user volumio by (uid=0)
Feb 01 19:19:12 volumio systemd[2260]: Starting Paths.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Paths.
Feb 01 19:19:12 volumio systemd[2260]: Starting Timers.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Timers.
Feb 01 19:19:12 volumio systemd[2260]: Starting Sockets.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Sockets.
Feb 01 19:19:12 volumio systemd[2260]: Starting Basic System.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Basic System.
Feb 01 19:19:12 volumio systemd[2260]: Starting Default.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Default.
Feb 01 19:19:12 volumio systemd[2260]: Startup finished in 26ms.
Feb 01 19:19:12 volumio systemd[1]: Started User Manager for UID 1000.
Feb 01 19:19:12 volumio sshd[2255]: lastlog_openseek: Couldn’t stat /var/log/lastlog: No such file or directory
Feb 01 19:19:12 volumio sshd[2255]: lastlog_openseek: Couldn’t stat /var/log/lastlog: No such file or directory
Feb 01 19:19:17 volumio sudo[2274]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -e
Feb 01 19:19:17 volumio sudo[2274]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)
Feb 01 19:20:10 volumio sudo[2274]: pam_unix(sudo:session): session closed for user root
Feb 01 19:20:12 volumio sudo[2335]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl
Feb 01 19:20:12 volumio sudo[2335]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)[/codepen]

[codepen]Feb 01 19:15:11 volumio sudo[1947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Feb 01 19:15:11 volumio sudo[1947]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:11 volumio sudo[1947]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:11 volumio sudo[1949]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:11 volumio sudo[1949]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:11 volumio sudo[1949]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::volumioGetBrowseSources
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::volumioGetState
Feb 01 19:15:12 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Feb 01 19:15:12 volumio sudo[1957]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:12 volumio sudo[1957]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:12 volumio sudo[1957]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
Feb 01 19:15:12 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Feb 01 19:15:12 volumio sudo[1964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:12 volumio sudo[1964]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:12 volumio volumio[743]: info: Listing playlists
Feb 01 19:15:12 volumio sudo[1964]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:13 volumio volumio[743]: info: CoreCommandRouter::volumioGetQueue
Feb 01 19:15:13 volumio volumio[743]: info: CoreStateMachine::getQueue
Feb 01 19:15:13 volumio volumio[743]: info: CorePlayQueue::getQueue
Feb 01 19:15:14 volumio volumio[743]: info: No input data
Feb 01 19:15:14 volumio volumio[743]: info: No input data
Feb 01 19:15:15 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:21 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:22 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:22 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:28 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: streaming_services , handleBrowseUri
Feb 01 19:15:32 volumio volumio[743]: info: CoreCommandRouter::volumioAddQueueItems
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::addQueueItems
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::addQueueItems
Feb 01 19:15:32 volumio volumio[743]: info: Adding Item to queue: tidal://song/100794834
Feb 01 19:15:32 volumio volumio[743]: info: Exploding uri tidal://song/100794834 in service streaming_services
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::saveQueue
Feb 01 19:15:32 volumio volumio[743]: info: CoreCommandRouter::volumioPushQueue
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::updateTrackBlock
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::getTrackBlock
Feb 01 19:15:32 volumio volumio[743]: info: CoreCommandRouter::volumioPlay
Feb 01 19:15:32 volumio volumio[743]: UNSET VOLATILE
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::play index 6
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService undefined
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::stop
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService undefined
Feb 01 19:15:32 volumio volumio[743]: UNSET VOLATILE
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::play index undefined
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService undefined
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:32 volumio volumio[743]: info: CoreStateMachine::startPlaybackTimer
Feb 01 19:15:32 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:32 volumio volumio[743]: info: [1549048532974] streamingServices::clearAddPlayTrack
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand stop
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand clear
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces system playlist update
Feb 01 19:15:33 volumio volumio[743]: info: Ignoring MPD Status Update
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand load "http://ab-pr-ak.audio.tidal.com/a97c414
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: info: ------------------------------ 9ms
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand add "http://ab-pr-ak.audio.tidal.com/a97c4149
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces system playlist update
Feb 01 19:15:33 volumio volumio[743]: info: Ignoring MPD Status Update
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService mpd
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand play
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: ------------------------------ 10ms
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces state update: player
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::getState
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand status
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Feb 01 19:15:33 volumio kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::parseState
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand playlistinfo
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info:
Feb 01 19:15:33 volumio volumio[743]: ---------------------------- MPD announces state update: player
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::getState
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand status
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::parseTrackInfo
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::pushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreCommandRouter::servicePushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::syncState
Feb 01 19:15:33 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:33 volumio volumio[743]: info: STATE SERVICE {“status”:“play”,“position”:0,“seek”:0,“duration”:218,"sample
Feb 01 19:15:33 volumio volumio[743]: info: CURRENT POSITION 6
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::syncState stateService play
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::syncState currentStatus stop
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:33 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:15:33 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:15:33 volumio volumio[743]: info: ------------------------------ 110ms
Feb 01 19:15:33 volumio volumio[743]: info: parsing response…
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::parseState
Feb 01 19:15:33 volumio sudo[1997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:33 volumio sudo[1997]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:33 volumio volumio[743]: info: ControllerMpd::sendMpdCommand playlistinfo
Feb 01 19:15:33 volumio volumio[743]: info: sending command…
Feb 01 19:15:33 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:15:34 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:15:34 volumio sudo[1997]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:34 volumio volumio[743]: info: parsing response…
Feb 01 19:15:34 volumio volumio[743]: info: ControllerMpd::parseTrackInfo
Feb 01 19:15:34 volumio volumio[743]: info: ControllerMpd::pushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::servicePushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::syncState
Feb 01 19:15:34 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:15:34 volumio volumio[743]: info: STATE SERVICE {“status”:“play”,“position”:0,“seek”:464,“duration”:218,“samp
Feb 01 19:15:34 volumio volumio[743]: info: CURRENT POSITION 6
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::syncState stateService play
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::syncState currentStatus play
Feb 01 19:15:34 volumio volumio[743]: info: Received an update from plugin. extracting info from payload
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:15:34 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:15:34 volumio sudo[2004]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:34 volumio sudo[2004]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:34 volumio volumio[743]: info: ------------------------------ 308ms
Feb 01 19:15:34 volumio sudo[2007]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:15:34 volumio sudo[2004]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:34 volumio sudo[2007]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:15:34 volumio sudo[2007]: pam_unix(sudo:session): session closed for user root
Feb 01 19:15:34 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:15:34 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:17:12 volumio systemd[1]: Starting Cleanup of Temporary Directories…
Feb 01 19:17:12 volumio systemd[1]: Started Cleanup of Temporary Directories.
Feb 01 19:17:55 volumio kernel: atc260x-rtc atc2603c-rtc.0: atc260x_rtc_settime(): 2019-02-01 19:17:55
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::volumioPause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::pause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::stPlaybackTimer
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::servicePause
Feb 01 19:19:05 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::servicePause
Feb 01 19:19:05 volumio volumio[743]: info: [1549048745864] streamingServices::pause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::setConsumeUpdateService mpd
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::pause
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::sendMpdCommand pause
Feb 01 19:19:05 volumio volumio[743]: info: sending command…
Feb 01 19:19:05 volumio volumio[743]: info: parsing response…
Feb 01 19:19:05 volumio volumio[743]: info:
Feb 01 19:19:05 volumio volumio[743]: ---------------------------- MPD announces state update: player
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::getState
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::sendMpdCommand status
Feb 01 19:19:05 volumio volumio[743]: info: sending command…
Feb 01 19:19:05 volumio volumio[743]: info: parsing response…
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::parseState
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::sendMpdCommand playlistinfo
Feb 01 19:19:05 volumio volumio[743]: info: sending command…
Feb 01 19:19:05 volumio volumio[743]: info: parsing response…
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::parseTrackInfo
Feb 01 19:19:05 volumio volumio[743]: info: ControllerMpd::pushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::servicePushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::syncState
Feb 01 19:19:05 volumio volumio[743]: info: CorePlayQueue::getTrack 6
Feb 01 19:19:05 volumio volumio[743]: info: STATE SERVICE {“status”:“pause”,“position”:0,“seek”:195953,“duration”:218,”
Feb 01 19:19:05 volumio volumio[743]: info: CURRENT POSITION 6
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::syncState stateService pause
Feb 01 19:19:05 volumio kernel: aotg_hub_endpoint_disable
Feb 01 19:19:05 volumio kernel: aotg_hcd aotg_hcd.1: ep5 index 1 from ep [out]
Feb 01 19:19:05 volumio kernel: aotg_hub_endpoint_disable
Feb 01 19:19:05 volumio kernel: aotg_hcd aotg_hcd.1: ep5 index 4 from ep [in]
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::syncState currentStatus pause
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::pushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::getState
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::volumioPushState
Feb 01 19:19:05 volumio volumio[743]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Feb 01 19:19:05 volumio volumio[743]: info: CoreStateMachine::stPlaybackTimer
Feb 01 19:19:05 volumio volumio[743]: info: ------------------------------ 58ms
Feb 01 19:19:05 volumio sudo[2245]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Feb 01 19:19:05 volumio sudo[2245]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 01 19:19:05 volumio sudo[2245]: pam_unix(sudo:session): session closed for user root
Feb 01 19:19:05 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:19:05 volumio volumio[743]: info: MyVolumio status changed
Feb 01 19:19:12 volumio sshd[2255]: Accepted password for volumio from 192.168.0.13 port 44274 ssh2
Feb 01 19:19:12 volumio sshd[2255]: pam_unix(sshd:session): session opened for user volumio by (uid=0)
Feb 01 19:19:12 volumio systemd[1]: Starting user-1000.slice.
Feb 01 19:19:12 volumio systemd[1]: Created slice user-1000.slice.
Feb 01 19:19:12 volumio systemd[1]: Starting User Manager for UID 1000…
Feb 01 19:19:12 volumio systemd[1]: Starting Session 2 of user volumio.
Feb 01 19:19:12 volumio systemd-logind[516]: New session 2 of user volumio.
Feb 01 19:19:12 volumio systemd[1]: Started Session 2 of user volumio.
Feb 01 19:19:12 volumio systemd[2260]: pam_unix(systemd-user:session): session opened for user volumio by (uid=0)
Feb 01 19:19:12 volumio systemd[2260]: Starting Paths.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Paths.
Feb 01 19:19:12 volumio systemd[2260]: Starting Timers.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Timers.
Feb 01 19:19:12 volumio systemd[2260]: Starting Sockets.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Sockets.
Feb 01 19:19:12 volumio systemd[2260]: Starting Basic System.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Basic System.
Feb 01 19:19:12 volumio systemd[2260]: Starting Default.
Feb 01 19:19:12 volumio systemd[2260]: Reached target Default.
Feb 01 19:19:12 volumio systemd[2260]: Startup finished in 26ms.
Feb 01 19:19:12 volumio systemd[1]: Started User Manager for UID 1000.
Feb 01 19:19:12 volumio sshd[2255]: lastlog_openseek: Couldn’t stat /var/log/lastlog: No such file or directory
Feb 01 19:19:12 volumio sshd[2255]: lastlog_openseek: Couldn’t stat /var/log/lastlog: No such file or directory
Feb 01 19:19:17 volumio sudo[2274]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -e
Feb 01 19:19:17 volumio sudo[2274]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)
Feb 01 19:20:10 volumio sudo[2274]: pam_unix(sudo:session): session closed for user root
Feb 01 19:20:12 volumio sudo[2335]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl
Feb 01 19:20:12 volumio sudo[2335]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)[/spoiler]

[EDIT: nope this only delayed the inevitable] Found the [almost] solution.
MPD internal buffer was set to 1024 which seems to be too low for some dacs. To fix:

  1. Go to volumio.local/dev
  2. Click to enable SSH
  3. Connect to Sparky over SSH
  4. Open the mpd config file (sudo nano /etc/mpd.conf, default password is volumio)
  5. Scroll down to MPD Internal Buffering
  6. Change the audio_buffer_size from 1024 to 8192
  7. Change the buffer_before_play to 10%
  8. Press Ctrl+x to exit nano, press y to confirm changes
  9. Reboot
    Sparky works as advertised now [NO IT DOESN’T]

Some questions to Volumio team:
Why are there configuration changes between versions for different boards (RaspberryPi has the buffer set to 8192 by default)
Why aren’t those changes documented?
Why aren’t the dropouts visible in the logs?

I’m planning to buy an usbridge and listen to usb SSD local drive and Spotify or qobuz/tidal accounts and a helix USB DAC/DSP for car use. Did you solve your problems? Is volumio updated even for this sparky board?

This is happening to me constantly now since the upgrade to 2.632. It used to happen occasionally and just hitting “rewind” reset the song and it usually worked. Sometimes I’d have to clear the queue and restart an album. But now it’s rare that I get through a single song before it fails. Any updates/fixes on this issue?

Can you raise buffer size and buffer before play values in playback option?
Please report back if that works