MacOS: Roon stops playing whenever a Time Machine backup starts [Roon Investigating]

Support
1

Roon Core Machine

2017 iMac Pro 10-core
MacOS 11.6 Big Sur

Networking Gear & Setup Details

Netgear Orbi

Connected Audio Devices

Schiit Bifrost 2 via RPi4/Ropieee

Number of Tracks in Library

300 albums

Description of Issue

Roon abruptly stops playing at exactly 44 minutes past the hour, every hour, like clockwork. It’s not a “dropout”; playback simply stops, and doesn’t resume until I press “play” again. When I noticed this pattern, I decided to do some digging, and it appears to be related to Apple Time Machine backups. At the time of playback interruption, there is a log message of the form:

03/05 19:45:01 Trace: [roonapi] [apiclient 192.168.1.101:50010] CONNECTION TIMEOUT
03/05 19:45:01 Trace: [client/roonbridges] [RoonBridge ropieee @ 192.168.1.101:43521] lost client connection. Retrying
03/05 19:45:01 Info: [roonapi] [apiclient 192.168.1.101:50010] disconnected

It is immediately preceded by a sequence of messages like the following:

03/05 19:44:34 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data
03/05 19:44:34 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data
03/05 19:44:34 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist '/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data'

This is no coincidence! Scanning through the logs, there is an endpoint disconnect (whether or not music was playing) at exactly 44 minutes past the hour, every hour, immediately preceded by activity related to Apple Time Machine. It appears that, at regular intervals, a Time Machine backup starts, causing a new virtual disk volume to be created by the operating system. Roon attempts to scan the new volume (I think?), which (for reasons I don’t understand) invariably causes my roonbridge endpoint to disconnect.

Needless to say, abrupt playback interruption has a devastating effect on my enjoyment of the music experience. I suspect this issue began with build 911 (and wasn’t fixed in the 913 update), as I don’t recall experiencing it before the 911 update. But I can’t say for certain.

Here’s the full log snippet at the time of a typical disconnect.

03/05 19:44:34 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data
03/05 19:44:34 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-184407/Macintosh HD - Data
03/05 19:44:34 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data
03/05 19:44:34 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-184407/Macintosh HD - Data
03/05 19:44:34 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist '/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data'
03/05 19:44:34 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist '/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-184407/Macintosh HD - Data'
03/05 19:44:35 Trace: [library] endmutation in 77ms
03/05 19:45:01 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
03/05 19:45:01 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
03/05 19:45:01 Trace: [roonapi] [apiclient 192.168.1.101:50010] CONNECTION TIMEOUT
03/05 19:45:01 Trace: [client/roonbridges] [RoonBridge ropieee @ 192.168.1.101:43521] lost client connection. Retrying
03/05 19:45:01 Info: [roonapi] [apiclient 192.168.1.101:50010] disconnected
03/05 19:45:01 Trace: [roonapi/registry] removing [apiclient 192.168.1.101:50010] => [org.ropieee.remote, RoPieee Remote Control V2 [ropieee] v4.017 by Spockfish <htenberge+ropieee@gmail.com>]
03/05 19:45:01 Info: [stats] 11238mb Virtual, 1791mb Physical, 815mb Managed
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":79553,"status":"Dropout"}
03/05 19:45:01 Warn: [rnet/RnetJsonClient] error writing to connection
03/05 19:45:01 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
03/05 19:45:01 Warn: could not run /usr/sbin/diskutil info -plist '/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-184407/Macintosh HD - Data' -- Exit code was: 1
03/05 19:45:01 Warn: could not run /usr/sbin/diskutil info -plist '/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/thucydides/2022-03-05-194432/Macintosh HD - Data' -- Exit code was: 1
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"samples":96000,"status":"Dropout"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [7] {"status":"Ended"}
03/05 19:45:01 Trace: [Bifrost] [Lossless, 24/192 QOBUZ FLAC => 24/192] [100% buf] [PLAYING @ 3:13/7:14] Heroin - The Velvet Underground / Nico
03/05 19:45:01 Trace: [client/roonbridges] [RoonBridge ropieee @ 192.168.1.101:43521] connecting (attempt 1)
03/05 19:45:01 Trace: [push] retrying connection in 93333ms
03/05 19:45:01 Trace: [broker/accounts] [heartbeat] now=3/6/2022 3:45:01 AM nextauthrefresh=3/6/2022 4:31:03 AM nextmachineallocate=3/6/2022 5:24:49 AM
03/05 19:45:01 Warn: [rnet/RnetJsonClient] error writing to connection
03/05 19:45:01 Info: [roonapi/transport] deactivating zone subscriptions
03/05 19:45:01 Info: [transport] destroyed zone Shield (Chromecast) was playing? False
03/05 19:45:01 Trace: [zone Shield (Chromecast)] Suspend
03/05 19:45:01 Info: [zone Shield (Chromecast)] Canceling Pending Sleep
03/05 19:45:01 Info: [zone Shield (Chromecast)] Canceling Pending Sleep
03/05 19:45:01 Warn: [raat/tcpaudiosource] send failed: The socket has been shut down
03/05 19:45:01 Trace: [transport/zonedisplay] [SHIELD-Android-TV-bac87838491b32b380b55e8a42973af3._googlecast._tcp.local] un-associated endpoint
03/05 19:45:01 Trace: [raatserver] [RaatServer thucydides @ 127.0.0.1:9200] lost client connection. Retrying
03/05 19:45:01 Trace: [raatserver] [RaatServer thucydides @ 127.0.0.1:9200] connecting (attempt 1)
03/05 19:45:01 Warn: [raat/tcpaudiosource] disconnecting + retrying
03/05 19:45:01 Info: [transport] destroyed zone iMac Pro was playing? False
03/05 19:45:01 Debug: [raat/tcpaudiosource] disconnecting
03/05 19:45:01 Trace: [zone iMac Pro] Suspend
03/05 19:45:01 Warn: [Bifrost] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
03/05 19:45:01 Info: [zone iMac Pro] Canceling Pending Sleep
03/05 19:45:01 Info: [zone iMac Pro] Canceling Pending Sleep
03/05 19:45:01 Debug: [raat/tcpaudiosource] connecting to 192.168.1.101:42573
03/05 19:45:01 Trace: [client/roonbridges] [RoonBridge ropieee @ 192.168.1.101:43521] connected
03/05 19:45:01 Trace: [rnet/RnetJsonClient] SENT {"request":"updates_subscribe"}
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] too many dropouts. stopping stream
03/05 19:45:01 Warn: [Bifrost] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] too many dropouts. stopping stream
03/05 19:45:01 Debug: FTMSI-B closed file for qo/0CC4DA8E; open files:0
03/05 19:45:01 Warn: [Bifrost] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] too many dropouts. stopping stream
03/05 19:45:01 Warn: [Bifrost] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
03/05 19:45:01 Debug: FTMSI-B qo/0CC4DA8E download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] too many dropouts. stopping stream
03/05 19:45:01 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
03/05 19:45:01 Trace: [raatserver] [RaatServer ropieee @ 192.168.1.101:9200] lost client connection. Retrying
03/05 19:45:01 Trace: [raatserver] [RaatServer ropieee @ 192.168.1.101:9200] connecting (attempt 1)
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] Endpoint Schiit Bifrost 2 Unison USB State Changed: Playing => Prepared
03/05 19:45:01 Debug: [raat/tcpaudiosource] disconnecting
03/05 19:45:01 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
03/05 19:45:01 Info: [transport] destroyed zone Bifrost was playing? True
03/05 19:45:01 Trace: [zone Bifrost] Suspend
03/05 19:45:01 Info: [library] recorded play for profile 8b524bfd-6a97-4d20-9dcc-b4c08777c6aa: mediaid=50:1:f016fa16-562e-4989-ace9-8644eb472c04 metadataid= contentid=202:0:33984068 libraryid=50:1:f016fa16-562e-4989-ace9-8644eb472c04 isfromradio=False isfrommix=False isfrommobile=
03/05 19:45:01 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 192000/24/2  Quality=Lossless
    Raat Device=Schiit Bifrost 2 Unison USB
    Output OutputType=Local_Alsa Quality=Lossless SubType= Model=Schiit Bifrost 2 Unison USB
------------------------------------------------------------
03/05 19:45:01 Debug: FTMSI-B closed file for qo/C0840F6D; open files:0
03/05 19:45:01 Debug: FTMSI-B qo/C0840F6D download status: AllBlocksDownloaded accessTimeout:False openFiles:0 prev:(AllBlocksDownloaded,False,1)
03/05 19:45:01 Info: [audio/env] [zoneplayer] All streams were disposed
03/05 19:45:01 Error: [raat/tcpaudiosource] connect failed: Object reference not set to an instance of an object
03/05 19:45:01 Info: [zone Bifrost] OnPlayFeedback Stopped
03/05 19:45:01 Warn: [raat/tcpaudiosource] disconnecting + retrying
03/05 19:45:01 Info: [zone Bifrost] Canceling Pending Sleep
03/05 19:45:01 Info: [zone Bifrost] Canceling Pending Sleep
03/05 19:45:01 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status":"Success","updates":{"is_supported":true,"status":"UpToDate","progress":null,"current_version":{"machine_value":100800880,"branch":"stable","display_value":"1.8 (build 880) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] Endpoint Schiit Bifrost 2 Unison USB State Changed: Prepared => Idle
03/05 19:45:01 Info: sleep 40ms after flush
03/05 19:45:01 Error: getting null client....
03/05 19:45:01 Trace: [library] finished with 25 dirty tracks 3 dirty albums 6 dirty performers 25 dirty works 25 dirty performances 0 clumping tracks, 0 clumping auxfiles 0 compute tracks, 0 deleted tracks, 0 tracks to (re)load, 0 tracks to retain, 0 auxfiles to (re)load, 0 auxfiles to retain, and 60 changed objects
03/05 19:45:01 Info: [Bifrost] [zoneplayer] BufferingTrack == NextTrack during ClearQueuedMedia, setting _stop_on_next_track_transition
03/05 19:45:01 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Disconnect
03/05 19:45:01 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect
03/05 19:45:01 Trace: [raatserver] [RaatServer thucydides @ 127.0.0.1:9200] connected
03/05 19:45:01 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
03/05 19:45:01 Debug: GMS: saving nav stack
03/05 19:45:01 Info: [library/albumdetails] found 1 ingroup alternates, 0 other alternates
03/05 19:45:01 Trace: [raatserver] [RaatServer ropieee @ 192.168.1.101:9200] connected
03/05 19:45:01 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
03/05 19:45:01 Info: [library/albumdetails] found 1 ingroup alternates, 0 other alternates
03/05 19:45:01 Info: [library/albumdetails] found 1 ingroup alternates, 0 other alternates
03/05 19:45:01 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"vendor": "Apple Inc.", "name": "iMac Pro Speakers", "device_id": "BuiltInSpeakerDevice", "discovery_data": {"vendor": "N/A", "version": "N/A", "unique_id": "cd4d9cc0-681b-7b85-bcb9-98fb8e88039d", "tcp_port": 49458, "raat_version": "1.1.38", "protocol_version": "3", "model": "N/A"}, "type": "coreaudio", "config": {"unique_id": "cd4d9cc0-681b-7b85-bcb9-98fb8e88039d", "output": {"type": "coreaudio", "device": "BuiltInSpeakerDevice", "name": "iMac Pro Speakers"}, "external_config": {}, "volume": {"type": "coreaudio", "device": "BuiltInSpeakerDevice"}}}, {"name": "System Output", "device_id": "default", "type": "coreaudio", "is_system_output": true, "config": {"unique_id": "9dc41aae-45fc-e174-5ae6-110686f5da5b", "output": {"type": "coreaudio", "device": "default", "name": "System Output"}, "external_config": {}, "volume": {"type": "coreaudio", "device": "default"}}}]}
03/05 19:45:01 Info: [raatserver] GOT DEVICE ef085935-eeb5-41bf-b9b7-d50b650bf955::BuiltInSpeakerDevice Type=coreaudio Name=iMac Pro Speakers Vendor=Apple Inc.
03/05 19:45:01 Info: [raatserver] GOT DEVICE ef085935-eeb5-41bf-b9b7-d50b650bf955::default Type=coreaudio Name=System Output 
03/05 19:45:01 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"BuiltInSpeakerDevice","subscription_id":"35"}
03/05 19:45:01 Info: [raatserver] [iMac Pro Speakers] connecting (attempt 1)
03/05 19:45:01 Info: [library/albumdetails] found 1 ingroup alternates, 0 other alternates
03/05 19:45:01 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"devices": [{"device_id": "hw:CARD=USB,DEV=0", "type": "alsa", "name": "Schiit Bifrost 2 Unison USB", "usb_id": "30be:1000", "vendor": "Schiit Audio", "discovery_data": {"tcp_port": 42019, "model": "N/A", "unique_id": "40246916-7124-858d-8618-f58cc2a93330", "raat_version": "1.1.38", "protocol_version": "3", "version": "N/A", "vendor": "N/A"}, "config": {"external_config": {}, "unique_id": "40246916-7124-858d-8618-f58cc2a93330", "output": {"dsd_mode": "none", "type": "alsa", "device": "hw:CARD=USB,DEV=0", "name": "Schiit Bifrost 2 Unison USB"}, "volume": {"type": "alsa", "device": "hw:CARD=USB,DEV=0"}}}], "status": "Success"}
03/05 19:45:01 Info: [raatserver] GOT DEVICE 705f64d7-7fc4-4673-9965-de9ea7201530::hw:CARD=USB,DEV=0 Type=alsa Name=Schiit Bifrost 2 Unison USB Vendor=Schiit AudioUsbId=30be:1000
03/05 19:45:01 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"hw:CARD=USB,DEV=0","subscription_id":"36"}
03/05 19:45:01 Info: [raatserver] [Schiit Bifrost 2 Unison USB] connecting (attempt 1)
03/05 19:45:01 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] Initializing RAAT session
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] Loading script raat.dat:protocol.lua as module protocol [2045 chars]
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] Loading script raat.dat:roon_tcp.lua [43548 chars]
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] Initializing RAAT session
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] Loading script raat.dat:protocol.lua as module protocol [2045 chars]
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] Loading script raat.dat:roon_tcp.lua [43548 chars]
03/05 19:45:01 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] RAAT Session initialized in 25ms
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] SENT [2]{"request":"info"}
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] SENT [3]{"request":"set_client_type","client_type":"Roon"}
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] GOT [2] {"flags":{"has_write_chmap":true},"platform":{"os":"osx","uname":{"version":"Darwin Kernel Version 20.6.0: Mon Aug 30 06:12:21 PDT 2021; root:xnu-7195.141.6~3/RELEASE_X86_64","release":"20.6.0","machine":"x86_64","nodename":"thucydides.local","sysname":"Darwin"}},"status":"Success","output":{"supported_formats":"88200/24/1|2,96000/24/1|2,44100/24/1|2,96000/16/1|2,88200/16/1|2,44100/16/1|2,48000/24/1|2,48000/16/1|2","info":{"config":{"type":"coreaudio","device":"BuiltInSpeakerDevice","name":"iMac Pro Speakers"}}},"volume":{"info":{"config":{"type":"coreaudio","device":"BuiltInSpeakerDevice"}},"is_supported":true},"source_selection":{"info":[],"is_supported":false},"info":{"unique_id":"cd4d9cc0-681b-7b85-bcb9-98fb8e88039d"},"transport":{"info":[],"is_supported":false}}
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] GOT [3] {"status":"Success"}
03/05 19:45:01 Trace: [raatserver] [iMac Pro Speakers] connected
03/05 19:45:01 Info: [transport] creating endpoint for raat device cd4d9cc0-681b-7b85-bcb9-98fb8e88039d
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] SENT [4]{"request":"subscribe_transport"}
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] SENT [5]{"request":"subscribe_controls","controller_id":"d91c328e-e73b-4918-b123-c96c1e14956c"}
03/05 19:45:01 Trace: [dspengine] created new dsp config {"version":3,"items":[{"type":"bs2b","enabled":false},{"type":"parametric_equalizer","enabled":false},{"type":"audeze_presets","enabled":false}]}
03/05 19:45:01 Trace: [transport/audeze] picking preset lowlatency 
03/05 19:45:01 Trace: [transport/audeze] picked null preset!
03/05 19:45:01 Trace: [music/searchindex]  removed: 1 albums, 1 tracks, 0 works, 2 performers, 0 labels, 0 genres
03/05 19:45:01 Trace: [music/searchindex]  added: 1 albums, 1 tracks, 0 works, 2 performers, 0 labels, 0 genres
03/05 19:45:01 Trace: [iMac Pro Speakers] [raatclient] GOT [5] {"controls":{"volume":{"mute":false,"max":100.0,"step":1.0,"type":"number","min":0.0,"info":{"config":{"type":"coreaudio","device":"BuiltInSpeakerDevice"}},"value":100}},"action":"Changed","status":"Success"}
03/05 19:45:01 Trace: [dbperf] flush 0 bytes, 0 ops in 39 ms (cumulative 166746436 bytes, 146941 ops in 20172 ms)
03/05 19:45:01 Trace: [library] endmutation in 408ms
03/05 19:45:01 Trace: [zone iMac Pro] Loading
03/05 19:45:01 Trace: [zone iMac Pro] Suspend
03/05 19:45:01 Info: [zone iMac Pro] Canceling Pending Sleep
03/05 19:45:01 Trace: [iMac Pro] [zoneplayer/raat] Endpoint iMac Pro Speakers Initial State: Idle
03/05 19:45:01 Info: [transport] created zone iMac Pro
03/05 19:45:01 Info: [transport]     with endpoint iMac Pro Speakers (23:1:cd4d9cc0-681b-7b85-bcb9-98fb8e88039d) [IsAvailable=True]
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] RAAT Session initialized in 39ms
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] SENT [2]{"request":"info"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] SENT [3]{"request":"set_client_type","client_type":"Roon"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [2] {"platform":{"uname":{"release":"5.10.76-1-SPCKFSH-v7l+","sysname":"Linux","nodename":"ropieee","machine":"armv7l","version":"#1 SMP PREEMPT Mon Nov 1 14:11:29 CET 2021"},"os":"linux"},"transport":{"is_supported":false,"info":[]},"flags":{"has_write_chmap":true},"status":"Success","source_selection":{"info":[],"is_supported":false},"volume":{"info":[],"is_supported":false},"output":{"info":{"config":{"dsd_mode":"none","type":"alsa","name":"Schiit Bifrost 2 Unison USB","device":"hw:CARD=USB,DEV=0"},"alsa_device":{"usbid":"30be:1000","id":"USB","longname":"Schiit Audio Schiit Bifrost 2 Unison USB at usb-0000:01:00.0-1.1, high speed","components":"USB","name":"Schiit Bifrost 2 Unison USB","mixername":"USB Mixer","driver":"USB-Audio"}},"supported_formats":"176400/32/1|2,44100/32/1|2,88200/24/1|2,88200/32/1|2,44100/24/1|2,44100/16/1|2,96000/24/1|2,48000/16/1|2,192000/32/1|2,96000/16/1|2,96000/32/1|2,176400/24/1|2,88200/16/1|2,192000/16/1|2,176400/16/1|2,48000/32/1|2,192000/24/1|2,48000/24/1|2"},"info":{"unique_id":"40246916-7124-858d-8618-f58cc2a93330"}}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [3] {"status":"Success"}
03/05 19:45:01 Trace: [raatserver] [Schiit Bifrost 2 Unison USB] connected
03/05 19:45:01 Info: [transport] creating endpoint for raat device 40246916-7124-858d-8618-f58cc2a93330
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] SENT [4]{"request":"subscribe_transport"}
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] SENT [5]{"request":"subscribe_controls","controller_id":"d91c328e-e73b-4918-b123-c96c1e14956c"}
03/05 19:45:01 Trace: [dspengine] created new dsp config {"version":3,"items":[{"type":"bs2b","enabled":false},{"type":"parametric_equalizer","enabled":false},{"type":"audeze_presets","enabled":false}]}
03/05 19:45:01 Trace: [transport/audeze] picking preset lowlatency 
03/05 19:45:01 Trace: [transport/audeze] picked null preset!
03/05 19:45:01 Trace: [Schiit Bifrost 2 Unison USB] [raatclient] GOT [5] {"controls":[],"action":"Changed","status":"Success"}
03/05 19:45:01 Trace: [library] endmutation in 14ms
03/05 19:45:01 Trace: [zone Bifrost] Loading
03/05 19:45:01 Trace: [zone Bifrost] Suspend
03/05 19:45:01 Info: [zone Bifrost] Canceling Pending Sleep
03/05 19:45:01 Trace: [Bifrost] [zoneplayer/raat] Endpoint Schiit Bifrost 2 Unison USB Initial State: Idle
03/05 19:45:01 Info: [transport] created zone Bifrost
03/05 19:45:01 Info: [transport]     with endpoint Schiit Bifrost 2 Unison USB (23:1:40246916-7124-858d-8618-f58cc2a93330) [IsAvailable=True]
03/05 19:45:01 Trace: [Bifrost] [Lossless, 24/192 QOBUZ FLAC => 24/192] [100% buf] [STOPPED @ 0:00] 
03/05 19:45:01 Trace: [zone iMac Pro] Loaded Queue=0 Tracks Swim=Inactive AutoSwim=True Loop=Disabled Shuffle=False
03/05 19:45:01 Trace: [zone Bifrost] Loaded Queue=112 Tracks Swim=Inactive AutoSwim=False Loop=Disabled Shuffle=False
03/05 19:45:01 Trace: [Bifrost] [Lossless, 24/192 QOBUZ FLAC => 24/192] [100% buf] [PAUSED @ 3:13/7:14] Heroin - The Velvet Underground / Nico
03/05 19:45:01 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect
03/05 19:45:01 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect
03/05 19:45:01 Debug: GMS: trying to save nav stack, but nav stack stuff was in progress
03/05 19:45:01 Debug: GET /image/zjjaaaaa.512.jpg
03/05 19:45:01 Trace: GetImageData[Remote](id=6343 spec=512 key=zjjaaaaa) => got from cache overalltime=0ms
03/05 19:45:01 Trace: GetImageData[Remote](id=6343 spec=512 key=zjjaaaaa) => got from cache overalltime=1ms
2

Only testing a hunch, what does your Folders page look like, under settings->storage ?

3

Here’s my Folders page. /Volumes/Roon is an attached dedicated SSD.

image
image2268×678 63.1 KB

4

I’m not promising this will help you but it might be worth looking over this thread here, feels similar.

5

I have no idea what’s causing the problem, but you could use TimeMachineEditor as a work around. It’s a fairly simple bit of software that allows you to schedule when Time Machine will run. I have mine set to block time machine from 8am to 1am. Not much help if you want to keep Time Machine running all the time, but it might help you to evade the problem until support can look into the cause.

1 Like
6

Thanks for the tip re: TimeMachineEditor! It’s a plausible workaround, but it’d be unfortunate if I had to compromise a core feature of my operating system in order for Roon’s most basic feature (music playback) to work properly.

What I’d really like is a response from someone from Roon. It’d be great to get an official acknowledgement of this issue, confirmation that disabling Time Machine is indeed the right workaround, and some indication of when it might be fixed.

But it’s been two weeks since I reported this issue, with no official response. Meanwhile, two updates have been released, but playback is still broken. Is posting to this forum actually the right way to get support? Or is there some other support channel I should be using instead?

Thanks,
Aaron

7

This is the right place, so let’s give @support a nudge to let them know you’re still waiting for a response.

8

Hey @Aaron_Siegel,

I’m very sorry it took us this long to react… :pensive:. Thanks all for the conversation, input and for tagging our team again :pray:t2:

Thank you for bringing up this topic, @Aaron_Siegel, and for sharing this much detail. I’ve passed on the feedback and our team is investigating.

Please, stay tuned :nerd_face:

10

No worries! I’m glad the team is investigating now - thanks for having a look. Let me know if there’s anything else I can do to help.

11

Hey @Aaron_Siegel,

Our team has discussed your case based on the information we have so far and what would be really helpful for thee next steps, is a full set of logs.

Could you please grab a set of logs from your Roon Core, zip up the entire Logs folder and upload it in our drive?

Please, do let us know once you’ve had a chance to do this — unfortunately, we don’t get upload notifications.

1 Like
12

@support I’m sorry for the slow response! I was traveling for several weeks and am just now getting caught up. I uploaded a full set of logs as roon-logs.zip under my name (Aaron Siegel).

I’m still experiencing this issue after the latest updates.

Thanks!

1 Like
16

Hey @Aaron_Siegel,

Thanks so much for helping us every step of the way so far. We appreciate the logs, as well as the information you’ve shared with us.

Could you please confirm:

  • whether TimeMachine backups are successfully completed?
  • is there sufficient disk space?

While we figure out what exactly is causing this issue, would you be able to consider either using the Time Machine Editor or disabling Time Machine altogether? This is only to avoid having playback be interrupted :nerd_face:

21

No worries! I really appreciate the responsiveness from support, and I’m sorry it’s turning out to be so problematic.

Time Machine backups complete normally, and there is plenty of free space on the backup drive (2.6 TB), system drive (218 GB), and Roon drive (367 GB).

I’ll try using Time Machine Editor for the time being. I’m curious if you’ve received reports of similar playback interruptions from other users though… if I’m the only one affected and it’s taking this long to debug, maybe it’s not worth it… every engineering hour spent on this is an hour less developing great new features :frowning: Perhaps the problem will eventually go away on its own after an OS or Roon upgrade, or I could set up a dedicated Roon core.

22

Hey @Aaron_Siegel,

Thanks a lot for the prompt reply and information. I have relayed it to our tech team. To our knowledge, this is not a widespread issue, hence our questions in trying to identify what might cause this behavior.

I’ll follow up as soon as I have next steps :nerd_face: