Hi Roon labs people,
I have several Raspberry Pi running roonbridge and for the most part they work great. However today I had to reboot the Windows 10 PC running Roon Core and when it restarted Roon was having trouble with one of the zones. The problem zone doesn’t show up in the list of zones but it is visible in the “group zones” view.
I looked at the logs and I saw it repeating about 10x/second this message:
01/01 19:32:30 Debug: NotifyCorruptZoneDatabases Exception LevelDb.Exception: IO error: C:\Users\ockers\AppData\Local\Roon\Database\Core\1309f473b5a443dcab7929109db394b8\transport\zone_1601378ca3848759d476a5ff6bbfad70ac3c.db\MANIFEST-000194: The handle is invalid.
at LevelDb.Database._CheckError(IntPtr err)
at LevelDb.Database..ctor(String path)
at Sooloos.Broker.Transport.ZoneDb..ctor(String dbpath)
at Sooloos.Broker.Transport.Zone..ctor(State state, Module module, Sooid zoneid, IEnumerable`1 endpoints)
01/01 19:32:30 Error: [transport] emptying out corrupt zone database 22:1:84a38c37-5987-76d4-a5ff-6bbfad70ac3c
01/01 19:32:30 Critical: scx: in OnExit: System.NullReferenceException: Object reference not set to an instance of an object.
at Sooloos.Broker.Transport.Zone._CancelPendingSleep()
at Sooloos.Broker.Transport.Module.NotifyCorruptZoneDatabases(IZone zone, Exception e)
at Sooloos.Broker.Transport.Zone..ctor(State state, Module module, Sooid zoneid, IEnumerable`1 endpoints)
at Sooloos.Broker.Transport.Module.ev_threadexit()
at Sooloos.SynchronizationContextThread.OnExit()
If I disable the zone, these error messages stop being written to the logs, only the normal activity log messages are written. If I click the blue Enable button, these messages restart.
I tried re-initializing the roon bridge by stopping roonbridge, deleting (rm -rf) /var/roon, and restarting roonbridge. I understand this will create a new distinct uuid and I was hoping this would cause the creation of a new zone. However, that’s not what happens. Do I need to follow the steps in this post to re-initialize the whole RAATServer index?
If it helps, here are the logs from roon bridge on raspberry pi and from roon core, when I start roonbridge on the pi. In these logs, my Android phone running Roon Remote is at IP 192.168.0.130.
From the raspberry pi:
01/01 19:29:17 Info: Starting RoonBridge v1.7 (build 571) stable on linuxarmv7hf
01/01 19:29:17 Trace: [rnet/RnetJsonServer] Listening on port 38905
01/01 19:29:17 Trace: [roonbridgehelperserver] SOOD announce
01/01 19:29:18 Trace: [rnet/RnetJsonServer] [client 192.168.0.19:56882] GOT {"request":"updates_subscribe"}
01/01 19:29:18 Trace: [rnet/RnetJsonServer] [client 192.168.0.130:49882] GOT {"request":"updates_subscribe"}
01/01 19:29:18 Trace: [rnet/RnetJsonServer] [client 192.168.0.19:56882] SENT NONFINAL {"status":"Success","updates":{"is_supported":true,"status":"UpToDate","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
01/01 19:29:18 Trace: [rnet/RnetJsonServer] [client 192.168.0.130:49882] SENT NONFINAL {"status":"Success","updates":{"is_supported":true,"status":"UpToDate","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
01/01 19:29:30 Trace: Successful POST response from https://push.roonlabs.com/push/1/connect
01/01 19:29:30 Trace: [push] connecting to 35.237.217.18:9200
01/01 19:29:30 Trace: [push] connected
01/01 19:29:47 Trace: [appupdater] initial check for updates
01/01 19:29:47 Trace: [rnet/RnetJsonServer] [client 192.168.0.19:56882] SENT NONFINAL {"status":"Changed","updates":{"is_supported":true,"status":"Checking","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
01/01 19:29:47 Trace: [rnet/RnetJsonServer] [client 192.168.0.130:49882] SENT NONFINAL {"status":"Changed","updates":{"is_supported":true,"status":"Checking","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
01/01 19:29:47 Debug: [base/updater] Checking for updates: https://updates.roonlabs.com/update/?v=2&serial=726E575E-CAA4-4DE6-8294-73C00E774AC8&userid=&platform=linuxarmv7hf&product=RoonBridge&branding=&curbranch=stable&version=100700571&branch=stable
01/01 19:29:47 Debug: [appupdater] Update not needed
01/01 19:29:47 Trace: [rnet/RnetJsonServer] [client 192.168.0.19:56882] SENT NONFINAL {"status":"Changed","updates":{"is_supported":true,"status":"UpToDate","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
01/01 19:29:47 Trace: [rnet/RnetJsonServer] [client 192.168.0.130:49882] SENT NONFINAL {"status":"Changed","updates":{"is_supported":true,"status":"UpToDate","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
The core logs these messages when I start the roon bridge as above:
01/01 19:29:18 Trace: [client/roonbridges] RoonBridge discovered: RoonBridge office @ 192.168.0.21:38905
01/01 19:29:18 Info: [client/roonbridges] GOT SERVER eaca5cc8-4008-e99e-3f04-1e52057b3f86::cc548bf7-f688-45d0-84c9-83ceb59663f6 @ 192.168.0.21:38905 office
01/01 19:29:18 Trace: [client/roonbridges] [RoonBridge office @ 192.168.0.21:38905] connecting (attempt 1)
01/01 19:29:18 Trace: [client/roonbridges] [RoonBridge office @ 192.168.0.21:38905] connected
01/01 19:29:18 Trace: [rnet/RnetJsonClient] SENT {"request":"updates_subscribe"}
01/01 19:29:18 Trace: [push] restarting connection (Unable to read data from the transport connection: A blocking operation was interrupted by a call to WSACancelBlockingCall.)
01/01 19:29:18 Trace: [push] retrying connection in 32499ms
01/01 19:29:18 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status":"Success","updates":{"is_supported":true,"status":"UpToDate","progress":null,"current_version":{"machine_value":100700571,"branch":"stable","display_value":"1.7 (build 571) stable"},"available_version":null,"update_mode":"AutoCompatible"}}
01/01 19:29:19 Trace: [amplifier] [zoneplayer/raat] sync snd_rpi_hifiberry_dac: realtime=114809828627473 rtt=500us offset=110148657627us delta=-307us drift=-34602us in 4079.618s (-8.482ppm, -30.535ms/hr)
01/01 19:29:20 Trace: [raat] RAATServer discovered: RaatServer office @ 192.168.0.21:38429
01/01 19:29:20 Info: [raatserver] GOT SERVER eaca5cc8-4008-e99e-3f04-1e52057b3f86::7d1565ea-1f54-49fc-9aad-ec54827313f5 @ 192.168.0.21:38429 office PROTOVER=1 RAATVER=1.1.38
01/01 19:29:20 Trace: [raatserver] [RaatServer office @ 192.168.0.21:38429] connecting (attempt 1)
01/01 19:29:20 Trace: [raatserver] [RaatServer office @ 192.168.0.21:38429] connected
01/01 19:29:20 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
01/01 19:29:20 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "hw:CARD=sndrpihifiberry,DEV=0", "type": "alsa", "name": "snd_rpi_hifiberry_amp"}]}
01/01 19:29:20 Info: [raatserver] GOT DEVICE 7d1565ea-1f54-49fc-9aad-ec54827313f5::hw:CARD=sndrpihifiberry,DEV=0 Type=alsa Name=snd_rpi_hifiberry_amp
When I click blue Enable button on Settings -> Audio the core logs this repeatedly:
01/01 19:32:29 Trace: [rnet/RnetJsonClient] SENT {"request":"get_device_config","device_id":"hw:CARD=sndrpihifiberry,DEV=0","options":{}}
01/01 19:32:29 Trace: [rnet/RnetJsonClient] GOT {"config_info": {"supported_formats": [{"sample_type": "pcm", "channels": 1, "sample_rate": 44100, "bits_per_sample": 16}, {"sample_type": "pcm", "channels": 1, "sample_rate": 44100, "bits_per_sample": 24}, {"sample_type": "pcm", "channels": 1, "sample_rate": 44100, "bits_per_sample": 32}, {"sample_type": "pcm", "channels": 1, "sample_rate": 48000, "bits_per_sample": 16}, {"sample_type": "pcm", "channels": 1, "sample_rate": 48000, "bits_per_sample": 24}, {"sample_type": "pcm", "channels": 1, "sample_rate": 48000, "bits_per_sample": 32}, {"sample_type": "pcm", "channels": 2, "sample_rate": 44100, "bits_per_sample": 16}, {"sample_type": "pcm", "channels": 2, "sample_rate": 44100, "bits_per_sample": 24}, {"sample_type": "pcm", "channels": 2, "sample_rate": 44100, "bits_per_sample": 32}, {"sample_type": "pcm", "channels": 2, "sample_rate": 48000, "bits_per_sample": 16}, {"sample_type": "pcm", "channels": 2, "sample_rate": 48000, "bits_per_sample": 24}, {"sample_type": "pcm", "channels": 2, "sample_rate": 48000, "bits_per_sample": 32}]}, "device_info": {"device_id": "hw:CARD=sndrpihifiberry,DEV=0", "type": "alsa", "name": "snd_rpi_hifiberry_amp"}, "status": "Success"}
01/01 19:32:29 Info: [settings/raatserver] generating intiial default config for alsa device hw:CARD=sndrpihifiberry,DEV=0
01/01 19:32:29 Trace: ---[ Performing autoconfig For snd_rpi_hifiberry_amp ]------------
01/01 19:32:29 Trace: Device Name: snd_rpi_hifiberry_amp
01/01 19:32:29 Trace: Device Type: alsa
01/01 19:32:29 Trace: Device LocalUniqueId: hw:CARD=sndrpihifiberry,DEV=0
01/01 19:32:29 Trace: Setting dsd_mode=none
01/01 19:32:29 Trace: ---------------------------------------------------------
01/01 19:32:29 Trace: [rnet/RnetJsonClient] SENT {"request":"set_device_config","device_id":"hw:CARD=sndrpihifiberry,DEV=0","config":{"unique_id":"84a38c37-5987-76d4-a5ff-6bbfad70ac3c","output":{"type":"alsa","device":"hw:CARD=sndrpihifiberry,DEV=0","name":"snd_rpi_hifiberry_amp","dsd_mode":"none"},"volume":{"type":"alsa","device":"hw:CARD=sndrpihifiberry,DEV=0"},"external_config":{}}}
01/01 19:32:29 Trace: [rnet/RnetJsonClient] GOT {"status": "Success"}
01/01 19:32:29 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"hw:CARD=sndrpihifiberry,DEV=0","subscription_id":"10"}
01/01 19:32:29 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "DeviceChanged", "device": {"device_id": "hw:CARD=sndrpihifiberry,DEV=0", "type": "alsa", "config": {"unique_id": "84a38c37-5987-76d4-a5ff-6bbfad70ac3c", "output": {"type": "alsa", "device": "hw:CARD=sndrpihifiberry,DEV=0", "name": "snd_rpi_hifiberry_amp", "dsd_mode": "none"}, "external_config": {}, "volume": {"type": "alsa", "device": "hw:CARD=sndrpihifiberry,DEV=0"}}, "name": "snd_rpi_hifiberry_amp", "discovery_data": {"tcp_port": 41745, "unique_id": "84a38c37-5987-76d4-a5ff-6bbfad70ac3c", "raat_version": "1.1.38", "vendor": "N/A", "version": "N/A", "protocol_version": "3", "model": "N/A"}}}
01/01 19:32:29 Info: [raatserver] [snd_rpi_hifiberry_amp] connecting (attempt 1)
01/01 19:32:29 Trace: [snd_rpi_hifiberry_amp] [raatclient] Initializing RAAT session
01/01 19:32:29 Trace: [snd_rpi_hifiberry_amp] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
01/01 19:32:29 Trace: [snd_rpi_hifiberry_amp] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
01/01 19:32:29 Trace: [snd_rpi_hifiberry_amp] [raatclient] Loading script raat.dat:protocol.lua as module protocol [2045 chars]
01/01 19:32:29 Trace: [snd_rpi_hifiberry_amp] [raatclient] Loading script raat.dat:roon_tcp.lua [43475 chars]
01/01 19:32:30 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] RAAT Session initialized in 278ms
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] SENT [2]{"request":"info"}
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] SENT [3]{"request":"set_client_type","client_type":"Roon"}
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] GOT [2] {"output":{"supported_formats":"48000/32/1|2,44100/16/1|2,48000/16/1|2,44100/24/1|2,44100/32/1|2,48000/24/1|2","info":{"config":{"name":"snd_rpi_hifiberry_amp","device":"hw:CARD=sndrpihifiberry,DEV=0","dsd_mode":"none","type":"alsa"},"alsa_device":{"name":"snd_rpi_hifiberry_amp","mixername":"","components":"sndrpihifiberry","longname":"snd_rpi_hifiberry_amp","driver":"HifiberryAmp","id":"sndrpihifiberry"}}},"transport":{"is_supported":false,"info":[]},"flags":{"has_write_chmap":true},"platform":{"os":"linux","uname":{"version":"#1 SMP Mon Jun 24 10:53:39 PDT 2019","sysname":"Linux","machine":"armv7l","nodename":"office.int.ockers.net","release":"4.14.114-v7+"}},"status":"Success","volume":{"is_supported":true,"info":{"config":{"device":"hw:CARD=sndrpihifiberry,DEV=0","type":"alsa"}}},"info":{"unique_id":"84a38c37-5987-76d4-a5ff-6bbfad70ac3c"},"source_selection":{"is_supported":false,"info":[]}}
01/01 19:32:30 Trace: [raatserver] [snd_rpi_hifiberry_amp] connected
01/01 19:32:30 Info: [transport] creating endpoint for raat device 84a38c37-5987-76d4-a5ff-6bbfad70ac3c
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] SENT [4]{"request":"subscribe_transport"}
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] SENT [5]{"request":"subscribe_controls","controller_id":"3bc4e592-69da-44ff-8b84-3fccc0dbedd3"}
01/01 19:32:30 Trace: [dspengine] created new dsp config {"version":3,"items":[{"type":"bs2b","enabled":false},{"type":"parametric_equalizer","enabled":false},{"type":"audeze_presets","enabled":false}]}
01/01 19:32:30 Trace: [transport/audeze] picking preset lowlatency
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] GOT [3] {"status":"Success"}
01/01 19:32:30 Trace: [transport/audeze] picked null preset!
01/01 19:32:30 Trace: [snd_rpi_hifiberry_amp] [raatclient] GOT [5] {"status":"Success","action":"Changed","controls":{"volume":{"value":55,"step":1.0,"type":"number","max":100.0,"mute":false,"info":{"config":{"device":"hw:CARD=sndrpihifiberry,DEV=0","type":"alsa"}},"min":0.0}}}
01/01 19:32:30 Trace: [push] restarting connection (Unable to read data from the transport connection: A blocking operation was interrupted by a call to WSACancelBlockingCall.)
01/01 19:32:30 Trace: [push] retrying connection in 68692ms
01/01 19:32:30 Debug: NotifyCorruptZoneDatabases Exception LevelDb.Exception: IO error: C:\Users\ockers\AppData\Local\Roon\Database\Core\1309f473b5a443dcab7929109db394b8\transport\zone_1601378ca3848759d476a5ff6bbfad70ac3c.db\MANIFEST-000194: The handle is invalid.
at LevelDb.Database._CheckError(IntPtr err)
at LevelDb.Database..ctor(String path)
at Sooloos.Broker.Transport.ZoneDb..ctor(String dbpath)
at Sooloos.Broker.Transport.Zone..ctor(State state, Module module, Sooid zoneid, IEnumerable`1 endpoints)
01/01 19:32:30 Error: [transport] emptying out corrupt zone database 22:1:84a38c37-5987-76d4-a5ff-6bbfad70ac3c
01/01 19:32:30 Critical: scx: in OnExit: System.NullReferenceException: Object reference not set to an instance of an object.
at Sooloos.Broker.Transport.Zone._CancelPendingSleep()
at Sooloos.Broker.Transport.Module.NotifyCorruptZoneDatabases(IZone zone, Exception e)
at Sooloos.Broker.Transport.Zone..ctor(State state, Module module, Sooid zoneid, IEnumerable`1 endpoints)
at Sooloos.Broker.Transport.Module.ev_threadexit()
at Sooloos.SynchronizationContextThread.OnExit()
Those last debug/error/critical messages repeat about 10x per second in the logs until I disable the zone. If I click the gears and disable the zone, then the errors stop spamming the logs.
“Device Setup” in the remote app never shows the dialog for setting up the zone.
Is there any easy way to recover from this or do I need to re-initialize the RAATServer directory?
Thanks,
Jim