RoonServer OOM-Kills on 32-Core Machine with Ubuntu 24.04 LTS (ref#BC92TE)

Neil_Carpenter · September 13, 2024, 2:06am

What’s happening?

· Something else

How can we help?

· I am experiencing freezes or crashes

Describe the issue

After not running Roon for awhile, I decided to set it up again and it hasn't gone well. After trying in a VM and getting frequent oom-kills (even with 16GB RAM for the VM), I decided to run it directly on the 32 core, 128 GB RAM bare metal machine. Roon isn't the only thing running on there but it still has plenty of headroom (Ubuntu 24.04 LTS, 32-64GB RAM free typically, CPU util running less than 5% on average).

I copied all the music locally (to a zfs pool running on a mirror set of spinning drives) and started importing. Importing is _incredibly_ slow -- out of about 200k songs, it processed and imported about 1500 in 12 hours. Additionally, the Roon client running on my MBP is continuously disconnecting.

This evening, I noticed that the service has stopped.

```
$ sudo service roonserver status
× roonserver.service - RoonServer
Loaded: loaded (/etc/systemd/system/roonserver.service; enabled; preset: enabled)
Active: failed (Result: oom-kill) since Thu 2024-09-12 04:44:36 EDT; 17h ago
Duration: 21h 11min 51.825s
Process: 3236 ExecStart=/opt/RoonServer/start.sh (code=killed, signal=TERM)
Main PID: 3236 (code=killed, signal=TERM)
CPU: 1d 1h 27min 6.147s

Sep 12 04:42:29 mona start.sh[3247]: Running
Sep 12 04:43:24 mona start.sh[3247]: Not responding
Sep 12 04:43:40 mona start.sh[3247]: Running
Sep 12 04:43:50 mona start.sh[3247]: Not responding
Sep 12 04:43:59 mona start.sh[3247]: Running
Sep 12 04:44:15 mona start.sh[3247]: Not responding
Sep 12 04:44:23 mona start.sh[3247]: Running
Sep 12 04:44:33 mona systemd[1]: roonserver.service: A process of this unit has been killed by the OOM killer.
Sep 12 04:44:36 mona systemd[1]: roonserver.service: Failed with result 'oom-kill'.
```

The log shows pretty dramatic memory util:

```
$ fgrep -ir "[stats]" /var/roon/RoonServer/Logs/RoonServer_log.txt | tail
09/12 04:41:44 Info: [stats] 98408mb Virtual, 26306mb Physical, 25084mb Managed, 357 Handles, 184 Threads
09/12 04:42:08 Info: [stats] 98167mb Virtual, 38289mb Physical, 37072mb Managed, 352 Handles, 94 Threads
09/12 04:42:29 Info: [stats] 98399mb Virtual, 38516mb Physical, 37302mb Managed, 346 Handles, 178 Threads
09/12 04:42:44 Info: [stats] 97806mb Virtual, 64360mb Physical, 63161mb Managed, 357 Handles, 106 Threads
09/12 04:42:59 Info: [stats] 97581mb Virtual, 22274mb Physical, 1496mb Managed, 358 Handles, 89 Threads
09/12 04:43:14 Info: [stats] 98391mb Virtual, 39528mb Physical, 38346mb Managed, 357 Handles, 182 Threads
09/12 04:43:40 Info: [stats] 98391mb Virtual, 50343mb Physical, 49168mb Managed, 345 Handles, 90 Threads
09/12 04:43:59 Info: [stats] 97622mb Virtual, 50393mb Physical, 49203mb Managed, 343 Handles, 97 Threads
09/12 04:44:16 Info: [stats] 98055mb Virtual, 66983mb Physical, 65793mb Managed, 358 Handles, 138 Threads
09/12 04:44:31 Info: [stats] 97758mb Virtual, 78985mb Physical, 77795mb Managed, 357 Handles, 100 Threads
```

This is an entirely greenfield, from scratch installation of Roon. I have no idea how to troubleshoot this.

Describe your network setup

Verizon G3100 FiOS modem/router; however, problem is self-contained (no network issues, everything is local to server).

daniel · September 13, 2024, 7:48pm

Hi @Neil_Carpenter,
Thanks for reaching out to us about this issue. The best way to start troubleshooting would be for the Tech Support team to take a look at your logs. Can you please use the directions found here and send over a set of logs to our File Uploader?

I also had a few questions to narrow down the potential cause.

Do the memory spikes happen when playing to a specific zone?
Under Roon settings (the gear icon) → Library what settings do you have for background audio analysis? Setting it to throttled can sometimes improve performance.

image1188×696 47.7 KB
Are you using any DSP features when the memory spikes happen?

Neil_Carpenter · September 13, 2024, 8:38pm

I uploaded the log files.

I haven’t played anything via Roon. I was waiting for it to finish importing music.
“Throttled” – the default value.
Having not played anything, I can’t imagine DSP settings would be impactful but I have changed nothing from the default settings.

Neil_Carpenter · September 14, 2024, 11:30pm

Any updates? I’ve had RoonServer stopped because of the memory consumption but I restarted it this evening just to have a look at what the growth in memory consumption looks like.

$ tail -f RoonServer_log.txt | fgrep "[stats]"
09/14 18:33:24 Info: [stats] 13772mb Virtual, 194mb Physical, 29mb Managed, 242 Handles, 158 Threads
09/14 18:33:39 Info: [stats] 14702mb Virtual, 804mb Physical, 552mb Managed, 276 Handles, 164 Threads
09/14 18:33:54 Info: [stats] 15878mb Virtual, 1581mb Physical, 985mb Managed, 277 Handles, 162 Threads
09/14 18:34:09 Info: [stats] 23085mb Virtual, 6603mb Physical, 5344mb Managed, 380 Handles, 216 Threads
09/14 18:34:24 Info: [stats] 29744mb Virtual, 13286mb Physical, 11891mb Managed, 380 Handles, 212 Threads
09/14 18:34:39 Info: [stats] 32886mb Virtual, 9872mb Physical, 8350mb Managed, 381 Handles, 211 Threads
09/14 18:34:54 Info: [stats] 31916mb Virtual, 15035mb Physical, 13512mb Managed, 379 Handles, 88 Threads
09/14 18:35:09 Info: [stats] 32694mb Virtual, 8356mb Physical, 3984mb Managed, 382 Handles, 190 Threads
09/14 18:35:24 Info: [stats] 32718mb Virtual, 8813mb Physical, 4534mb Managed, 382 Handles, 193 Threads
09/14 18:35:39 Info: [stats] 33592mb Virtual, 8489mb Physical, 6901mb Managed, 381 Handles, 184 Threads
09/14 18:35:54 Info: [stats] 32719mb Virtual, 13102mb Physical, 11599mb Managed, 382 Handles, 74 Threads
09/14 18:36:09 Info: [stats] 32759mb Virtual, 11776mb Physical, 10340mb Managed, 382 Handles, 83 Threads
...
09/14 19:21:43 Info: [stats] 61574mb Virtual, 22730mb Physical, 20847mb Managed, 380 Handles, 81 Threads
09/14 19:21:58 Info: [stats] 61654mb Virtual, 11240mb Physical, 4535mb Managed, 380 Handles, 95 Threads
09/14 19:22:13 Info: [stats] 61638mb Virtual, 34147mb Physical, 32320mb Managed, 380 Handles, 89 Threads
09/14 19:22:29 Info: [stats] 61902mb Virtual, 18642mb Physical, 16733mb Managed, 380 Handles, 125 Threads
09/14 19:22:44 Info: [stats] 61606mb Virtual, 44754mb Physical, 42566mb Managed, 380 Handles, 85 Threads
09/14 19:22:59 Info: [stats] 61574mb Virtual, 28903mb Physical, 27068mb Managed, 380 Handles, 85 Threads
09/14 19:23:14 Info: [stats] 61606mb Virtual, 18245mb Physical, 16328mb Managed, 380 Handles, 89 Threads
09/14 19:23:29 Info: [stats] 62143mb Virtual, 20856mb Physical, 10751mb Managed, 380 Handles, 156 Threads
09/14 19:23:44 Info: [stats] 61614mb Virtual, 31862mb Physical, 30035mb Managed, 380 Handles, 87 Threads
09/14 19:23:59 Info: [stats] 61662mb Virtual, 19472mb Physical, 17640mb Managed, 380 Handles, 96 Threads
09/14 19:24:14 Info: [stats] 61662mb Virtual, 12618mb Physical, 2530mb Managed, 380 Handles, 96 Threads
09/14 19:24:29 Info: [stats] 62303mb Virtual, 32458mb Physical, 30619mb Managed, 381 Handles, 176 Threads
09/14 19:24:44 Info: [stats] 61630mb Virtual, 18586mb Physical, 16743mb Managed, 380 Handles, 88 Threads
09/14 19:24:59 Info: [stats] 61598mb Virtual, 13534mb Physical, 3067mb Managed, 380 Handles, 84 Threads

In an hour, virtual memory consumption has topped 60GB and physical memory consumption keeps see-sawing but is topping out over 44GB. Nothing is playing, the only thing that’s going on is audio analysis (still “throttled”).

noris · September 16, 2024, 8:10pm

Hi @Neil_Carpenter ,

We’ve enabled diagnostics mode for your account to get a better idea of this issue. I do see a few instances of memory suddenly jumping, we will consult with the team to see if we can better understand why. In the meantime, can you try to set both Background and On-Demand Audio Analysis to Off and let us know if that triggers any change in behavior? It does appear quite some analysis work is still happening in the logging.

Neil_Carpenter · September 17, 2024, 1:21am

I’m not sure this is an improvement – I can’t actually connect with a client to disable background/on-demand audio analysis because none of them will connect anymore. They sit at the animated Roon “please wait” logo, flashing occasionally as they seem to disconnect and reconnect.

Neil_Carpenter · September 17, 2024, 10:54pm

RoonServer continues to run but continues to be unavailable to clients. Any idea what’s going on based on your diagnostics?

Neil_Carpenter · September 18, 2024, 12:22pm

After rebooting the server, clients are connecting now, so background and on-demand analysis is disabled.

Of course, those are things that I would like to have on so I’m looking forward to your analysis.

Neil_Carpenter · September 18, 2024, 12:41pm

Spoke too soon. While I was able to interact from a client for a short period of time, now I’m getting the Roon jellyfish and/or “Please wait for your server” and/or “Something’s wrong”. Absolutely no indication of what’s going on in RoonServer logs.

09/18 08:37:19 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63601=>100.125.108.117:9332] Connected
09/18 08:37:19 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63601=>100.125.108.117:9332] Initialized Fresh Session
09/18 08:37:19 Trace: [remoting/brokerserver] killing old client from b6d9fe1d-4778-4ff0-880c-387e003ca654 because we have a new one
09/18 08:37:19 Info: [remoting/serverconnectionv2] Client connected: 100.86.243.81:63601
09/18 08:37:19 Trace: [raat] [sood] Refreshing device list
09/18 08:37:19 Trace: [raatserver] [sood] Refreshing device list
09/18 08:37:19 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/18 08:37:19 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001455 DisplayValue='2.0 (build 1455) production' Branch='production' } }
09/18 08:37:19 Debug: [easyhttp] [152] POST to https://api.roonlabs.net/discovery/1/query returned after 427 ms, status code: 200, request body size: 74 B
09/18 08:37:19 Debug: [easyhttp] [153] GET to https://api.roonlabs.net/messaging/1/api/messages/abc7fa18-ddb4-4ab5-a358-bbbcfe19fa91 returned after 170 ms, status code: 200, request body size: 0 B
09/18 08:37:29 Debug: [easyhttp] [154] POST to https://api.roonlabs.net/device-map/1/register returned after 185 ms, status code: 200, request body size: 9 KB
09/18 08:37:29 Trace: [devicemap] device map updated
09/18 08:37:32 Info: [stats] 29067mb Virtual, 6893mb Physical, 5800mb Managed, 380 Handles, 206 Threads
09/18 08:37:47 Info: [stats] 28930mb Virtual, 4785mb Physical, 3690mb Managed, 380 Handles, 184 Threads
09/18 08:38:02 Info: [stats] 28296mb Virtual, 7104mb Physical, 5555mb Managed, 381 Handles, 105 Threads
09/18 08:38:17 Info: [stats] 28168mb Virtual, 6986mb Physical, 5895mb Managed, 380 Handles, 89 Threads
09/18 08:38:32 Info: [stats] 31400mb Virtual, 5233mb Physical, 4116mb Managed, 380 Handles, 95 Threads
09/18 08:38:47 Info: [stats] 31834mb Virtual, 5275mb Physical, 4153mb Managed, 380 Handles, 151 Threads
09/18 08:39:03 Info: [remoting/serverconnectionv2] Client disconnected: 100.86.243.81:63601
09/18 08:39:03 Info: [remoting/serverconnectionv2] Client disconnected: 100.74.150.129:59053
09/18 08:39:03 Info: [stats] 31836mb Virtual, 11198mb Physical, 10086mb Managed, 380 Handles, 150 Threads
09/18 08:39:03 Trace: [raatserver] [RaatServer alucard @ 100.74.150.129:9200] lost client connection. Retrying
09/18 08:39:03 Trace: [raatserver] [RaatServer alucard @ 100.74.150.129:9200] connecting (attempt 1)
09/18 08:39:03 Info: [transport] destroyed zone alucard was playing? False
09/18 08:39:03 Trace: [zone alucard] Suspend
09/18 08:39:03 Info: [zone alucard] Canceling Pending Sleep
09/18 08:39:03 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63680=>100.125.108.117:9332] Connected
09/18 08:39:03 Warn: [remoting/brokerserver] [initconn 100.86.243.81:63680=>100.125.108.117:9332] failed: System.Exception: incomplete receive
   at Sooloos.Broker.Distributed.InitConnectionV2.Go()
09/18 08:39:03 Trace: [remoting/brokerserver] [initconn 100.74.150.129:61117=>100.125.108.117:9332] Connected
09/18 08:39:03 Warn: [remoting/brokerserver] [initconn 100.74.150.129:61117=>100.125.108.117:9332] failed: System.Exception: incomplete receive
   at Sooloos.Broker.Distributed.InitConnectionV2.Go()
09/18 08:39:03 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63703=>100.125.108.117:9332] Connected
09/18 08:39:03 Info: [zone alucard] Canceling Pending Sleep
09/18 08:39:03 Trace: [remoting/brokerserver] [initconn 100.74.150.129:61133=>100.125.108.117:9332] Connected
09/18 08:39:03 Trace: [remoting/brokerserver] [initconn 100.74.150.129:61133=>100.125.108.117:9332] Resumed Session
09/18 08:39:03 Trace: [raatserver] [RaatServer alucard @ 100.74.150.129:9200] connected
09/18 08:39:03 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
09/18 08:39:03 Trace: [remoting/remotingprotocolv2] resume send 18 messages, 0KiB
09/18 08:39:03 Error: [cast/client] [alucard._googlecast._tcp.local] Exception writing message to stream:
09/18 08:39:03 Trace: [raat] [sood] Refreshing device list
09/18 08:39:03 Trace: [raatserver] [sood] Refreshing device list
09/18 08:39:03 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "1E6D0677-0000-0000-061D-0103803C2278", "name": "LG HDR 4K", "type": "coreaudio", "vendor": "GSM"}, {"device_id": "AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1", "config": {"output": {"exclusive_mode": true, "type": "coreaudio", "name": "blafili B3", "device": "AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1", "integer_mode": true, "dsd_mode": "none"}, "external_config": {}, "unique_id": "05c57ba6-ee84-1e90-0846-db0fc54d6620", "volume": {"device": "AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1", "type": "coreaudio"}}, "name": "blafili B3", "type": "coreaudio", "vendor": "QTIL", "usb_id": "0a12:4007", "discovery_data": {"raat_version": "1.1.39", "tcp_port": 59098, "unique_id": "05c57ba6-ee84-1e90-0846-db0fc54d6620", "version": "N/A", "model": "N/A", "protocol_version": "3", "vendor": "N/A"}}, {"device_id": "BuiltInSpeakerDevice", "name": "Mac mini Speakers", "type": "coreaudio", "vendor": "Apple Inc."}, {"device_id": "default", "config": {"external_config": {}, "unique_id": "cd97611f-31eb-515b-2cd7-00be891c5322", "output": {"name": "System Output", "type": "coreaudio", "device": "default"}, "volume": {"type": "coreaudio", "device": "default"}}, "name": "System Output", "type": "coreaudio", "is_system_output": true}]}
09/18 08:39:03 Info: [raatserver] GOT DEVICE b16b3f6a-34e6-47a7-90e6-361fe7c8315f::1E6D0677-0000-0000-061D-0103803C2278 Type=coreaudio Name=LG HDR 4K Vendor=GSM
09/18 08:39:03 Info: [raatserver] GOT DEVICE b16b3f6a-34e6-47a7-90e6-361fe7c8315f::AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1 Type=coreaudio Name=blafili B3 Vendor=QTILUsbId=0a12:4007
09/18 08:39:03 Info: [raatserver] GOT DEVICE b16b3f6a-34e6-47a7-90e6-361fe7c8315f::BuiltInSpeakerDevice Type=coreaudio Name=Mac mini Speakers Vendor=Apple Inc.
09/18 08:39:03 Info: [raatserver] GOT DEVICE b16b3f6a-34e6-47a7-90e6-361fe7c8315f::default Type=coreaudio Name=System Output
09/18 08:39:03 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1","subscription_id":"5"}
09/18 08:39:03 Info: [raatserver] [blafili B3] connecting (attempt 1)
09/18 08:39:03 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
09/18 08:39:03 Trace: [blafili B3] [raatclient] Initializing RAAT session
09/18 08:39:10 Trace: [blafili B3] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
09/18 08:39:10 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63703=>100.125.108.117:9332] Resumed Session
09/18 08:39:10 Trace: [remoting/remotingprotocolv2] resume send 73 messages, 3KiB
09/18 08:39:10 Info: [remoting/serverconnectionv2] Client disconnected: 100.86.243.81:63601
09/18 08:39:10 Trace: [remoting/brokerserver] [initconn 100.74.150.129:61142=>100.125.108.117:9332] Connected
09/18 08:39:10 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63711=>100.125.108.117:9332] Connected
09/18 08:39:10 Info: [remoting/serverconnectionv2] Client disconnected: 100.74.150.129:59053
09/18 08:39:10 Trace: [remoting/brokerserver] [initconn 100.86.243.81:63711=>100.125.108.117:9332] Resumed Session
09/18 08:39:10 Trace: [remoting/remotingprotocolv2] resume send 76 messages, 3KiB
09/18 08:39:10 Trace: [remoting/brokerserver] [initconn 100.74.150.129:61142=>100.125.108.117:9332] Resumed Session
09/18 08:39:10 Trace: [remoting/remotingprotocolv2] resume send 6 messages, 0KiB
09/18 08:39:11 Debug: [easyhttp] [156] POST to https://api.roonlabs.net/discovery/1/query returned after 7997 ms, status code: 200, request body size: 74 B
09/18 08:39:11 Info: [cast] lost device CastDevice[DeviceId=alucard._googlecast._tcp.local, Name=Chromecast Ultra, Address=192.168.1.7] because it disconnected
09/18 08:39:11 Trace: [raat] [sood] Refreshing device list
09/18 08:39:11 Trace: [raatserver] [sood] Refreshing device list
09/18 08:39:11 Trace: [raat] [sood] Refreshing device list
09/18 08:39:11 Trace: [raatserver] [sood] Refreshing device list
09/18 08:39:11 Trace: [blafili B3] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
09/18 08:39:11 Warn: [blafili B3] [raatclient] RAAT Session timed out during initialization
09/18 08:39:11 Trace: [raat] [sood] Refreshing device list
09/18 08:39:11 Trace: [raatserver] [sood] Refreshing device list
09/18 08:39:11 Trace: [raatserver] [blafili B3] client connection failed. Retrying in 500ms
09/18 08:39:11 Info: [raatserver] [blafili B3] connecting (attempt 2)
09/18 08:39:11 Trace: [blafili B3] [raatclient] Initializing RAAT session
09/18 08:39:11 Trace: [blafili B3] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
09/18 08:39:11 Trace: [blafili B3] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
09/18 08:39:11 Trace: [blafili B3] [raatclient] Loading script raat.dat:protocol.lua as module protocol [2045 chars]
09/18 08:39:11 Trace: [blafili B3] [raatclient] Loading script raat.dat:roon_tcp.lua [45404 chars]
09/18 08:39:11 Trace: [blafili B3] [raatclient] RAAT Session initialized in 14ms
09/18 08:39:11 Trace: [blafili B3] [raatclient] SENT [2]{"request":"info"}
09/18 08:39:11 Trace: [blafili B3] [raatclient] SENT [3]{"request":"set_client_type","client_type":"Roon"}
09/18 08:39:11 Trace: [blafili B3] [raatclient] GOT [2] {"source_selection":{"is_supported":false,"info":[]},"status":"Success","flags":{"has_write_chmap":true},"output":{"supported_formats":"48000/16/1|2,44100/16/1|2","info":{"config":{"name":"blafili B3","type":"coreaudio","dsd_mode":"none","integer_mode":true,"device":"AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1","exclusive_mode":true}}},"platform":{"os":"osx","uname":{"sysname":"Darwin","version":"Darwin Kernel Version 23.6.0: Mon Jul 29 21:14:21 PDT 2024; root:xnu-10063.141.2~1/RELEASE_ARM64_T8103","release":"23.6.0","machine":"arm64","nodename":"alucard.local"}},"volume":{"is_supported":true,"info":{"config":{"type":"coreaudio","device":"AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1"}}},"transport":{"is_supported":false,"info":[]},"info":{"version":"N/A","unique_id":"05c57ba6-ee84-1e90-0846-db0fc54d6620","protocol_version":"3","model":"N/A","vendor":"N/A","raat_version":"1.1.39"}}
09/18 08:39:11 Trace: [raatserver] [blafili B3] connected
09/18 08:39:11 Info: [transport] creating endpoint for raat device 5f9ca015-270a-8a8a-e820-3e68883d58c1
09/18 08:39:11 Trace: [blafili B3] [raatclient] SENT [4]{"request":"subscribe_transport"}
09/18 08:39:11 Trace: [blafili B3] [raatclient] SENT [5]{"request":"subscribe_controls","controller_id":"25a180d0-2917-4434-890e-120e445ddcf2"}
09/18 08:39:11 Trace: [dspengine] created new dsp config {"version":3,"items":[{"type":"■■2b","enabled":false},{"type":"parametric_equalizer","enabled":false},{"type":"audeze_presets","enabled":false}]}
09/18 08:39:11 Trace: [transport/audeze] picking preset lowlatency
09/18 08:39:11 Trace: [transport/audeze] picked null preset!
09/18 08:39:11 Trace: [blafili B3] [raatclient] GOT [3] {"status":"Success"}
09/18 08:39:11 Trace: [zone alucard] Loading from /var/roon/RoonServer/Database/Core/abc7fa18ddb44ab5a358bbbcfe19fa91/transport/zone_160115a09c5f0a278a8ae8203e68883d58c1.db
09/18 08:39:11 Trace: [zone alucard] Suspend
09/18 08:39:11 Info: [zone alucard] Canceling Pending Sleep
09/18 08:39:11 Trace: [alucard] [zoneplayer/raat] Endpoint blafili B3 Initial State: Idle
09/18 08:39:11 Info: [transport] created zone alucard
09/18 08:39:11 Info: [transport]     with endpoint blafili B3 (23:1:5f9ca015-270a-8a8a-e820-3e68883d58c1) [IsAvailable=True]
09/18 08:39:11 Trace: [blafili B3] [raatclient] GOT [5] {"controls":{"volume":{"max":100.0,"type":"number","value":100,"min":0.0,"step":1.0,"mute":false,"info":{"config":{"type":"coreaudio","device":"AppleUSBAudioEngine:QTIL:blafili B3:ABCDEF0123456789:1"}}}},"status":"Success","action":"Changed"}
09/18 08:39:18 Info: [stats] 32861mb Virtual, 6187mb Physical, 5061mb Managed, 383 Handles, 207 Threads
09/18 08:39:21 Debug: [easyhttp] [157] POST to https://api.roonlabs.net/device-map/1/register returned after 91 ms, status code: 200, request body size: 9 KB
09/18 08:39:21 Trace: [devicemap] device map updated
09/18 08:39:33 Info: [stats] 32115mb Virtual, 4781mb Physical, 3659mb Managed, 383 Handles, 111 Threads
09/18 08:39:33 Debug: [easyhttp] [158] POST to https://api.roonlabs.net/discovery/1/query returned after 87 ms, status code: 200, request body size: 74 B
09/18 08:39:48 Info: [stats] 32227mb Virtual, 7006mb Physical, 5893mb Managed, 383 Handles, 128 Threads
09/18 08:40:03 Info: [stats] 31971mb Virtual, 4970mb Physical, 2997mb Managed, 383 Handles, 92 Threads

Neil_Carpenter · September 18, 2024, 12:54pm

All of that aside, with audio analysis disabled, I see the same pattern of ever increasing memory consumption.

09/18 08:23:08 Info: [stats] 21335mb Virtual, 4892mb Physical, 3865mb Managed, 375 Handles, 101 Threads
09/18 08:23:23 Info: [stats] 21151mb Virtual, 4472mb Physical, 2967mb Managed, 375 Handles, 79 Threads
09/18 08:23:39 Info: [stats] 21577mb Virtual, 4132mb Physical, 2904mb Managed, 375 Handles, 90 Threads
09/18 08:23:54 Info: [stats] 21930mb Virtual, 5257mb Physical, 4229mb Managed, 375 Handles, 131 Threads
09/18 08:24:09 Info: [stats] 21769mb Virtual, 6034mb Physical, 5013mb Managed, 375 Handles, 107 Threads
09/18 08:24:24 Info: [stats] 22457mb Virtual, 6199mb Physical, 5178mb Managed, 375 Handles, 101 Threads
09/18 08:24:39 Info: [stats] 25562mb Virtual, 5239mb Physical, 3475mb Managed, 375 Handles, 103 Threads
09/18 08:24:54 Info: [stats] 25965mb Virtual, 4605mb Physical, 3102mb Managed, 375 Handles, 154 Threads
09/18 08:25:09 Info: [stats] 25443mb Virtual, 4284mb Physical, 3215mb Managed, 375 Handles, 90 Threads
09/18 08:25:25 Info: [stats] 25516mb Virtual, 5190mb Physical, 4137mb Managed, 383 Handles, 100 Threads
09/18 08:25:40 Info: [stats] 25540mb Virtual, 4316mb Physical, 3263mb Managed, 375 Handles, 117 Threads
09/18 08:25:55 Info: [stats] 26205mb Virtual, 5039mb Physical, 3985mb Managed, 375 Handles, 184 Threads
09/18 08:26:10 Info: [stats] 25435mb Virtual, 5389mb Physical, 4329mb Managed, 375 Handles, 85 Threads
...
09/18 08:46:54 Info: [stats] 36687mb Virtual, 10882mb Physical, 9396mb Managed, 384 Handles, 189 Threads
09/18 08:47:09 Info: [stats] 36855mb Virtual, 6488mb Physical, 4994mb Managed, 382 Handles, 208 Threads
09/18 08:47:25 Info: [stats] 36005mb Virtual, 10175mb Physical, 8678mb Managed, 394 Handles, 100 Threads
09/18 08:47:40 Info: [stats] 36246mb Virtual, 8747mb Physical, 7233mb Managed, 382 Handles, 132 Threads
09/18 08:47:56 Info: [stats] 36246mb Virtual, 5604mb Physical, 4114mb Managed, 385 Handles, 132 Threads
09/18 08:48:11 Info: [stats] 36109mb Virtual, 6483mb Physical, 4984mb Managed, 382 Handles, 111 Threads
09/18 08:48:26 Info: [stats] 36799mb Virtual, 6354mb Physical, 4851mb Managed, 383 Handles, 202 Threads
09/18 08:48:41 Info: [stats] 36366mb Virtual, 7583mb Physical, 6052mb Managed, 381 Handles, 147 Threads
09/18 08:48:56 Info: [stats] 36366mb Virtual, 8096mb Physical, 6584mb Managed, 383 Handles, 147 Threads
09/18 08:49:11 Info: [stats] 35973mb Virtual, 8246mb Physical, 5072mb Managed, 381 Handles, 94 Threads
09/18 08:49:26 Info: [stats] 35933mb Virtual, 6390mb Physical, 4874mb Managed, 381 Handles, 89 Threads
09/18 08:49:44 Info: [stats] 36342mb Virtual, 9398mb Physical, 7914mb Managed, 381 Handles, 146 Threads
09/18 08:49:59 Info: [stats] 36855mb Virtual, 6448mb Physical, 3950mb Managed, 381 Handles, 208 Threads
09/18 08:50:15 Info: [stats] 36855mb Virtual, 7956mb Physical, 6480mb Managed, 384 Handles, 206 Threads
09/18 08:50:30 Info: [stats] 36727mb Virtual, 8824mb Physical, 7346mb Managed, 381 Handles, 189 Threads
09/18 08:50:45 Info: [stats] 36743mb Virtual, 13354mb Physical, 11877mb Managed, 382 Handles, 194 Threads
09/18 08:51:01 Info: [stats] 36751mb Virtual, 16360mb Physical, 14884mb Managed, 383 Handles, 189 Threads
09/18 08:51:16 Info: [stats] 36855mb Virtual, 8083mb Physical, 4609mb Managed, 397 Handles, 209 Threads
09/18 08:51:31 Info: [stats] 36021mb Virtual, 8359mb Physical, 6911mb Managed, 383 Handles, 100 Threads
09/18 08:51:46 Info: [stats] 36270mb Virtual, 9676mb Physical, 8163mb Managed, 383 Handles, 135 Threads

benjamin · September 18, 2024, 7:05pm

Hey @Neil_Carpenter,

Thanks for the update! COuld you please send over another set of server logs, but this time also include the Varlog? Here’s the upload link:

File Uploader

Have you been able to reproduce this issue in a non-VM setup? Note that we’re not able to support any Roon devices running in a virtual environment.

We’ll be on standby for those logs!

Neil_Carpenter · September 18, 2024, 10:28pm

I’ve uploaded the latest RoonServer logs; however, I have no idea what you mean by “the Varlog”. Please advise.

Neil_Carpenter · September 19, 2024, 7:10pm

Have you been able to reproduce this issue in a non-VM setup? Note that we’re not able to support any Roon devices running in a virtual environment.

As I said in the original problem description:

This is not, currently, running on a VM. It’s running on bare metal.

This has now been going on for a week and Roon remains essentially non-functional. What have you determined from your additional logging?

Neil_Carpenter · September 20, 2024, 12:06pm

$ sudo service roonserver status
× roonserver.service - RoonServer
     Loaded: loaded (/etc/systemd/system/roonserver.service; enabled; preset: enabled)
     Active: failed (Result: oom-kill) since Thu 2024-09-19 19:27:20 EDT; 12h ago
   Duration: 1d 11h 30min 31.261s
    Process: 4658 ExecStart=/opt/RoonServer/start.sh (code=killed, signal=TERM)
   Main PID: 4658 (code=killed, signal=TERM)
        CPU: 1d 18h 6min 11.369s

Sep 19 19:15:43 mona start.sh[2200674]: Running
Sep 19 19:16:46 mona start.sh[2200674]: Not responding
Sep 19 19:16:54 mona start.sh[2200674]: Running
Sep 19 19:17:10 mona start.sh[2200674]: Not responding
Sep 19 19:17:16 mona start.sh[2200674]: Running
Sep 19 19:18:35 mona start.sh[2200674]: Not responding
Sep 19 19:18:44 mona start.sh[2200674]: Running
Sep 19 19:27:20 mona systemd[1]: roonserver.service: A process of this unit has been killed by the OOM killer.
Sep 19 19:27:20 mona systemd[1]: roonserver.service: Failed with result 'oom-kill'.
Sep 19 19:27:20 mona systemd[1]: roonserver.service: Consumed 1d 18h 6min 11.369s CPU time, 45.9G memory peak, 364.0M memory swap peak.

Nothing illustrative in the RoonServer log, just more of the same:

09/19 19:27:00 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:00 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:00 Info: [stats] 99230mb Virtual, 50884mb Physical, 51210mb Managed, 390 Handles, 204 Threads
09/19 19:27:00 Debug: [easyhttp] [427] GET to https://api.roonlabs.net/messaging/1/api/messages/abc7fa18-ddb4-4ab5-a358-bbbcfe19fa91 returned after 117 ms, status code: 200, request body size: 0 B
09/19 19:27:02 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53265=>100.125.108.117:9332] Connected
09/19 19:27:02 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53265=>100.125.108.117:9332] Initialized Session because we couldn't resume
09/19 19:27:02 Trace: [remoting/brokerserver] killing old client from 7feb2743-161a-4873-8251-04f920bbb56c because we have a new one
09/19 19:27:02 Info: [remoting/serverconnectionv2] Client connected: 100.74.150.129:53265
09/19 19:27:02 Trace: [raat] [sood] Refreshing device list
09/19 19:27:02 Trace: [raatserver] [sood] Refreshing device list
09/19 19:27:02 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:02 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:04 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53310=>100.125.108.117:9332] Connected
09/19 19:27:04 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53310=>100.125.108.117:9332] Initialized Session because we couldn't resume
09/19 19:27:04 Trace: [remoting/brokerserver] killing old client from 7feb2743-161a-4873-8251-04f920bbb56c because we have a new one
09/19 19:27:04 Info: [remoting/serverconnectionv2] Client connected: 100.74.150.129:53310
09/19 19:27:04 Trace: [raat] [sood] Refreshing device list
09/19 19:27:05 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:05 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:05 Trace: [raatserver] [sood] Refreshing device list
09/19 19:27:05 Debug: [easyhttp] [428] POST to https://api.roonlabs.net/discovery/1/query returned after 81 ms, status code: 200, request body size: 74 B
09/19 19:27:05 Debug: [easyhttp] [429] GET to https://api.roonlabs.net/messaging/1/api/messages/abc7fa18-ddb4-4ab5-a358-bbbcfe19fa91 returned after 145 ms, status code: 200, request body size: 0 B
09/19 19:27:08 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53361=>100.125.108.117:9332] Connected
09/19 19:27:08 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53361=>100.125.108.117:9332] Initialized Session because we couldn't resume
09/19 19:27:08 Trace: [remoting/brokerserver] killing old client from 7feb2743-161a-4873-8251-04f920bbb56c because we have a new one
09/19 19:27:08 Info: [remoting/serverconnectionv2] Client connected: 100.74.150.129:53361
09/19 19:27:08 Trace: [raat] [sood] Refreshing device list
09/19 19:27:08 Trace: [raatserver] [sood] Refreshing device list
09/19 19:27:08 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:08 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:09 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53402=>100.125.108.117:9332] Connected
09/19 19:27:09 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53402=>100.125.108.117:9332] Initialized Session because we couldn't resume
09/19 19:27:09 Trace: [remoting/brokerserver] killing old client from 7feb2743-161a-4873-8251-04f920bbb56c because we have a new one
09/19 19:27:09 Info: [remoting/serverconnectionv2] Client connected: 100.74.150.129:53402
09/19 19:27:09 Trace: [raat] [sood] Refreshing device list
09/19 19:27:09 Trace: [raatserver] [sood] Refreshing device list
09/19 19:27:10 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:10 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:10 Debug: [easyhttp] [430] GET to https://api.roonlabs.net/messaging/1/api/messages/abc7fa18-ddb4-4ab5-a358-bbbcfe19fa91 returned after 164 ms, status code: 200, request body size: 0 B
09/19 19:27:12 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53442=>100.125.108.117:9332] Connected
09/19 19:27:12 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53442=>100.125.108.117:9332] Initialized Session because we couldn't resume
09/19 19:27:12 Trace: [remoting/brokerserver] killing old client from 7feb2743-161a-4873-8251-04f920bbb56c because we have a new one
09/19 19:27:12 Info: [remoting/serverconnectionv2] Client connected: 100.74.150.129:53442
09/19 19:27:12 Trace: [raat] [sood] Refreshing device list
09/19 19:27:12 Trace: [raatserver] [sood] Refreshing device list
09/19 19:27:12 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:12 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:14 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53489=>100.125.108.117:9332] Connected
09/19 19:27:14 Trace: [remoting/brokerserver] [initconn 100.74.150.129:53489=>100.125.108.117:9332] Initialized Session because we couldn't resume
09/19 19:27:14 Trace: [remoting/brokerserver] killing old client from 7feb2743-161a-4873-8251-04f920bbb56c because we have a new one
09/19 19:27:14 Info: [remoting/serverconnectionv2] Client connected: 100.74.150.129:53489
09/19 19:27:14 Trace: [raat] [sood] Refreshing device list
09/19 19:27:14 Trace: [raatserver] [sood] Refreshing device list
09/19 19:27:15 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=25a180d0-2917-4434-890e-120e445ddcf2 BrokerName='mona' }
09/19 19:27:15 Trace: [remoting/remotingserverv2] SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=200001462 DisplayValue='2.0 (build 1462) production' Branch='production' } }
09/19 19:27:15 Info: [stats] 99230mb Virtual, 75635mb Physical, 76087mb Managed, 394 Handles, 204 Threads
09/19 19:27:15 Debug: [easyhttp] [431] GET to https://api.roonlabs.net/messaging/1/api/messages/abc7fa18-ddb4-4ab5-a358-bbbcfe19fa91 returned after 151 ms, status code: 200, request body size: 0 B

Uploaded another set of logs anyway.

benjamin · September 23, 2024, 8:27pm

Hey @Neil_Carpenter,

Here you go:

Zip that folder up and upload it here: File Uploader

Thanks

Neil_Carpenter · September 24, 2024, 7:51pm

You really want the entirety of /var/log? I have no idea what sensitive data may be in there and I have no easy way to redact it.

What are you looking for in /var/log? Why isn’t there sufficient data in the diagnostic mode that you enabled eight (8) days ago?

noris · September 25, 2024, 5:29pm

Hi @Neil_Carpenter ,

Are you able to upload a few snippets from var-log that shows the OOM errors, along with a few lines above & below the OOM error? The diagnostic mode we activated does not access var-log and there’s nothing too obvious causing the error in var-log, so we will need to investigate a bit deeper.

Neil_Carpenter · October 4, 2024, 8:18pm

I’ve left RoonServer running for awhile and, while it hasn’t actually been OOM killed, it remains not actually functional.

First, the service itself routinely shows as “not responding”:

$ journalctl -xefu roonserver
...
Oct 04 15:46:50 mona start.sh[2826277]: Not responding
Oct 04 15:46:55 mona start.sh[2826277]: Running
Oct 04 15:47:21 mona start.sh[2826277]: Not responding
Oct 04 15:47:26 mona start.sh[2826277]: Running
Oct 04 15:50:27 mona start.sh[2826277]: Not responding
Oct 04 15:50:42 mona start.sh[2826277]: Running
Oct 04 15:52:37 mona start.sh[2826277]: Not responding
Oct 04 15:52:45 mona start.sh[2826277]: Running
Oct 04 15:53:03 mona start.sh[2826277]: Not responding
Oct 04 15:53:13 mona start.sh[2826277]: Running
Oct 04 15:55:59 mona start.sh[2826277]: Not responding
Oct 04 15:56:04 mona start.sh[2826277]: Running
Oct 04 15:56:22 mona start.sh[2826277]: Not responding
Oct 04 15:56:37 mona start.sh[2826277]: Running
Oct 04 15:57:23 mona start.sh[2826277]: Not responding
Oct 04 15:57:28 mona start.sh[2826277]: Running
Oct 04 16:01:07 mona start.sh[2826277]: Not responding
Oct 04 16:01:12 mona start.sh[2826277]: Running
Oct 04 16:02:23 mona start.sh[2826277]: Not responding
Oct 04 16:02:30 mona start.sh[2826277]: Running

It’s been like this more-or-less since it was restarted. I just restarted it and it was “not responding” about two minutes after it started.

Oct 04 16:05:26 mona systemd[1]: Started roonserver.service - RoonServer.
░░ Subject: A start job for unit roonserver.service has finished successfully
░░ Defined-By: systemd
░░ Support: http://www.ubuntu.com/support
░░
░░ A start job for unit roonserver.service has finished successfully.
░░
░░ The job identifier is 568367.
Oct 04 16:05:26 mona start.sh[937811]: 00:00:00.000 Info:  get lock file path: /tmp/.rnsgem0-
Oct 04 16:05:26 mona start.sh[937811]: 00:00:00.002 Info:  GetLockFile, fd: 35
Oct 04 16:05:26 mona start.sh[937811]: 00:00:00.002 Info:  GetLockFile, res: 0
Oct 04 16:05:26 mona start.sh[937811]: 00:00:00.002 Trace: Nope, we are the only one running
Oct 04 16:05:26 mona start.sh[937811]: Initializing
Oct 04 16:05:26 mona start.sh[937811]: Started
Oct 04 16:05:27 mona start.sh[937833]: aac_fixed decoder found, checking libavcodec version...
Oct 04 16:05:27 mona start.sh[937833]: has mp3float: 1, aac_fixed: 1
Oct 04 16:05:31 mona start.sh[937811]: Running
Oct 04 16:06:22 mona start.sh[937833]: error while seeking stream to mdat pos
Oct 04 16:06:22 mona start.sh[937833]: atom with <8 bytes is invalid(top) unknown chunk id:
Oct 04 16:06:22 mona start.sh[937833]: [1B blob data]
Oct 04 16:06:22 mona start.sh[937833]: [1B blob data]
Oct 04 16:07:21 mona start.sh[937811]: Not responding
Oct 04 16:07:27 mona start.sh[937811]: Running

The Roon client frequently shows the message indicating it’s been disconnected. When it is connected, it continues to show that it’s adding music to the library but incredibly slowly. In the 22 days since I opened this thread, it’s imported about 88000 local tracks and has about 44000 remaining.

I’ve uploaded the latest RoonServer log and syslog from today.

Neil_Carpenter · October 4, 2024, 8:41pm

Funny enough, I tried playing some music after I posted that last reply. In less than twenty minutes, the server managed to get itself OOM killed.

Oct 04 16:12:28 mona start.sh[937811]: Running
Oct 04 16:14:35 mona start.sh[937811]: Not responding
Oct 04 16:14:40 mona start.sh[937811]: Running
Oct 04 16:15:33 mona start.sh[937811]: Not responding
Oct 04 16:15:41 mona start.sh[937811]: Running
Oct 04 16:23:36 mona start.sh[937811]: Not responding
Oct 04 16:23:44 mona start.sh[937811]: Running
Oct 04 16:23:54 mona start.sh[937811]: Not responding
Oct 04 16:23:59 mona start.sh[937811]: Running
Oct 04 16:24:05 mona systemd[1]: roonserver.service: A process of this unit has been killed by the OOM killer.
░░ Subject: A process of roonserver.service unit has been killed by the OOM killer.
░░ Defined-By: systemd
░░ Support: http://www.ubuntu.com/support
░░
░░ A process of unit @UNIT has been killed by the Linux kernel out-of-memory (OOM)
░░ killer logic. This usually indicates that the system is low on memory and that
░░ memory needed to be freed. A process associated with roonserver.service has been determined
░░ as the best process to terminate and has been forcibly terminated by the
░░ kernel.
░░
░░ Note that the memory pressure might or might not have been caused by roonserver.service.
Oct 04 16:24:05 mona systemd[1]: roonserver.service: Failed with result 'oom-kill'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: http://www.ubuntu.com/support
░░
░░ The unit roonserver.service has entered the 'failed' state with result 'oom-kill'.
Oct 04 16:24:05 mona systemd[1]: roonserver.service: Consumed 38min 56.522s CPU time.
░░ Subject: Resources consumed by unit runtime
░░ Defined-By: systemd
░░ Support: http://www.ubuntu.com/support
░░
░░ The unit roonserver.service completed and consumed the indicated resources.

How much memory was it using? Let’s check RoonServer log:

 10/04 16:23:59 Info: [stats] 79966mb Virtual, 55358mb Physical, 53158mb Managed, 370 Handles, 211 Threads

55GB of physical RAM? What on Earth would RoonServer need that much memory for? It’s been up for less than twenty minutes at this point.

There’s nothing helpful in the RoonServer log. A tail of it shows

$ tail RoonServer_log.txt
10/04 16:23:55 Debug: [easyhttp] [311] GET to https://api.roonlabs.net/discover/1/albums/121:0:MW0001983512/recommended/albums?profileId=310bb2d0-f801-4249-9642-b562248286f1&c=tidal-us&tidal=max returned after 147 ms, status code: 200, request body size: 0 B
10/04 16:23:55 Debug: [easyhttp] [309] GET to https://api.roonlabs.net/discover/1/albums/62:1:9b717223-ab82-4918-8f82-c1324876d53b/recommended/albums?profileId=310bb2d0-f801-4249-9642-b562248286f1&c=tidal-us&tidal=max returned after 216 ms, status code: 200, request body size: 0 B
10/04 16:23:55 Trace: [zone alucard] Loaded Queue=62 Tracks Swim=Inactive AutoSwim=True Loop=Disabled Shuffle=False
10/04 16:23:55 Trace: [alucard] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PAUSED @ 3:54/4:10] Magdalena - A Perfect Circle
10/04 16:23:55 Trace: [library] endmutation in 17ms
10/04 16:23:55 Trace: [zone livingroom] Loaded Queue=0 Tracks Swim=Inactive AutoSwim=True Loop=Disabled Shuffle=False
10/04 16:23:55 Trace: [zone bedroom] Loaded Queue=0 Tracks Swim=Inactive AutoSwim=True Loop=Disabled Shuffle=False
10/04 16:23:55 Debug: [easyhttp] [313] GET to https://api.roonlabs.net/metadatatext/1/blobs?objectId=191:0:1235225&type=biography&sourceLangs=Rovi-albums:en,Wikipedia:en,Rovi-artists:en,Rovi-compositions:en&c=tidal-us&tidal=max returned after 62 ms, status code: 200, request body size: 0 B
10/04 16:23:55 Debug: [easyhttp] [305] GET to https://api.roonlabs.net/discover/1/albums/121:0:MW0001983512/recommended/albums?profileId=310bb2d0-f801-4249-9642-b562248286f1&c=tidal-us&tidal=max returned after 470 ms, status code: 200, request body size: 0 B
10/04 16:23:59 Info: [stats] 79966mb Virtual, 55358mb Physical, 53158mb Managed, 370 Handles, 211 Threads

What led up to it? Nothing interesting from a system perspective.

2024-10-04T16:23:49.053878-04:00 mona tailscaled[2644]: open-conn-track: timeout opening (TCP 100.125.108.117:48576 => 192.168.1.7:8008) to node [aSfc2]; online=yes, lastRecv=5s
2024-10-04T16:23:54.138176-04:00 mona start.sh[937811]: Not responding
2024-10-04T16:23:54.183908-04:00 mona tailscaled[2644]: open-conn-track: timeout opening (TCP 100.125.108.117:48576 => 192.168.1.7:8008) to node [aSfc2]; online=yes, lastRecv=0s
2024-10-04T16:23:59.238409-04:00 mona start.sh[937811]: Running
2024-10-04T16:24:00.265425-04:00 mona tailscaled[2644]: open-conn-track: timeout opening (TCP 100.125.108.117:48576 => 192.168.1.7:8008) to node [aSfc2]; online=yes, lastRecv=6s
2024-10-04T16:24:05.023349-04:00 mona kernel: apps.plugin invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
...
2024-10-04T16:24:05.046028-04:00 mona kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=netdata.service,mems_allowed=0,global_oom,task_memcg=/system.slice/roonserver.service,task=RoonAppliance,pid=937833,uid=0
2024-10-04T16:24:05.046029-04:00 mona kernel: Out of memory: Killed process 937833 (RoonAppliance) total-vm:86473344kB, anon-rss:66264100kB, file-rss:2468kB, shmem-rss:0kB, UID:0 pgtables:134368kB oom_score_adj:0
2024-10-04T16:24:05.100735-04:00 mona systemd[1]: roonserver.service: A process of this unit has been killed by the OOM killer.
2024-10-04T16:24:05.103968-04:00 mona systemd[1]: roonserver.service: Failed with result 'oom-kill'.
2024-10-04T16:24:05.104424-04:00 mona systemd[1]: roonserver.service: Consumed 38min 56.522s CPU time.
2024-10-04T16:24:08.193276-04:00 mona kernel: oom_reaper: reaped process 937833 (RoonAppliance), now anon-rss:0kB, file-rss:2468kB, shmem-rss:0kB

Some regular tailscaled messages, RoonServer going unresponsive and responsive again, and RoonServer consuming a tremendous amount of memory.

benjamin · October 4, 2024, 9:01pm

Thanks for the detailed follow-up @Neil_Carpenter - we’ll share with development and see what next steps look like.