One of my snd_rpi_hifiberry_amp zones is causing NotifyCorruptZoneDatabases Exception

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

1 Like

Moved to support

Hi @James_Ockers,

Thanks for reaching out! I haven’t seen a similar trace before, so let me inquire with our QA team and get back to you!

Hi @James_Ockers,

Thanks for your patience here while I checked with the team on this one!

Can you please try to see if you are able to set up a fresh Roon database and verify if this behavior still occurs?

  • Make a Backup of your current Roon Database
  • Exit out of Roon
  • Navigate to your Roon’s Database Location
  • Find the folder that says “Roon”
  • Rename the “Roon” folder to “Roon_old”
  • Reinstall the Roon App from our Downloads Page to generate a new Roon folder
  • Use the fresh database, reboot the Core a few times and verify if the error re-occurs

Hi @noris,

I set up a fresh Roon database as per your instructions and although it lost all my metadata the zones all init and work fine now.

I’m not sure what caused the database to become corrupt for the one zone but it would be great if there was a way to purge a single zone record (or force it to completely re-init) without having to lose the whole database with all preferences, saved songs, zone names, etc.

Thanks
Jim

1 Like

Hello @James_Ockers,

Thanks for letting us know that you were able to resolve this issue with the fresh backup in place!

Do you have any backups from when the issue occurred? I mentioned your case to QA and it would be interesting to note if the issue reproduces if you try to restore a backup to the same Core.

If you wish to perform this test, please ensure you have a new backup of your Roon database before starting.

A post was merged into an existing topic: 1.8 Audio devices in Settings but not in Zone picker [Ticket In]

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.