Almost there @xxx! You’re missing one part of her resume and why that’s relevant and appropriate to the name of my machine. I’m sure you’ll get it, so we’ll have to figure out how I can send you the dollar as soon as you come through. And yes, I’m a huge fan of her as well.
Casey
I give up, see my PM.
Can you explain this a little more? I don’t think Noris was suggesting moving over the database or storage configuration – just the Roon license.
If you have any other machine capable of running Roon and can spin up a Core there for some testing, it will help us understand whether this issue is localized to the one machine, or something else related to your environment.
My experience is that when things “suddenly stop working” it’s often somewhere tricky to pin down – a bad cable, failing RAM, a silent firmware update, etc. That’s why tests like this tend to be really useful.
Noris can absolutely keep working on this, but this is a somewhat exotic setup, and over and over we’ve found that the fastest way forward in those cases is to simplify things as much as possible, add the complexity back in, and see where along the way things break.
It’s not a fun process, but it’s very very effective. In any event, we appreciate your patience @Casey_Leedom.
Hello @Casey_Leedom,
I wanted to check in with you here to see how’s it going and if you have made any progress on this issue. I just received some feedback from the QA team regarding your case.
They have suggested moving the DNS + DHCP back to the primary router instead of the current computer to see if that helps resolve the situation. If you want to try another machine without having to swap the drives, you can try mounting the drives via network instead.
Please let me know when possible if you are able to make progress on this issue with my above suggestions.
Thanks,
Noris
Hey there @noris,
Sorry about the delay in getting back to you — insert excuses involving managing a Christmas Orphans’ Dinner, Prime Ribs, etc.
I was going to try working the Name Server angle. My current /etc/bind/db.root is the default one that’s distributed with bind which contains [A-M].ROOT-SERVERS.NET. I should probably use my ISP, ComCast’s, DNS Servers plus possibly other popular professional DNS servers. But grep’ing through /var/roon/RoonServer/Logs/* for “NameResolutionFailure” only shows some failures from December 16th, trying to look up accounts5.roonlabs.com … I suppose that could be a serious enough issue that would cause the Roon Core server to jam up, but if so, a serious message into the System Log should have been generated … But again, nothing since the 16th and the Roon Core server stopped working again last night.
And it’s still not working now that I finally have time to look at things. Looking at /var/roon/RoonServer/Logs/RoonServer_log.txt I see that the last 4500 lines are of the form:
12/25 21:42:09 Info: [brokerserver] Client connected: 10.13.100.101:56273
12/25 21:42:09 Trace: [SOOD] Adding User IP 10.13.100.101
12/25 21:42:09 Trace: [raat] [sood] Refreshing device list
12/25 21:42:09 Trace: [raatserver] [sood] Refreshing device list
12/25 21:42:09 Info: [brokerserver] Client disconnected: 10.13.100.101:56273
12/25 21:42:09 Info: [brokerserver] Client connected: 10.13.100.101:56274
12/25 21:42:09 Trace: [SOOD] Adding User IP 10.13.100.101
12/25 21:42:09 Trace: [raat] [sood] Refreshing device list
12/25 21:42:09 Trace: [raatserver] [sood] Refreshing device list
12/25 21:42:09 Trace: SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=73f38150-87f2-4715-be58-6b4a28ba13f9 BrokerName='hypatia' }
12/25 21:42:09 Trace: SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=100500363 DisplayValue='1.5 (build 363) stable' Branch='stable' } }
12/25 21:42:09 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
12/25 21:42:09 Trace: [push] retrying connection in 84163ms
12/25 21:42:09 Critical: scx: System.NullReferenceException: Object reference not set to an instance of an object
at Sooloos_Broker_Api_Broker_Adapter.Serialize (System.Object obj, System.IO.Stream stream) [0x00177] in <5688c850c7ba4c9aacd47453605b5145>:0
at Sooloos.Broker.Remoting.RemotingServer._PutObject (System.Object o, System.IO.Stream stream, System.Boolean inline) [0x0010b] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.Broker.Remoting.RemotingServer+<>c__DisplayClass28_0.<OnGetService>b__0 (Base.Result`1[T] result) [0x0002b] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.Broker.Distributed.ServerConnection.OnGetService (System.Guid guid, Base.ResultCallback`1[T] cb_result) [0x0001e] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Broker.Remoting.RemotingServer.OnGetService (System.Int32 rid, System.Byte[] body) [0x0001f] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.Broker.Remoting.RemotingServer+<>c__DisplayClass22_0.<OnRequestReceived>b__0 () [0x00011] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.SynchronizationContextThread+<>c__DisplayClass45_0.<Post>b__0 (System.Object _) [0x00000] in <474fc6b46f7646c587f524cda12acaf9>:0
at Sooloos.SynchronizationContextThread._Dispatch (Sooloos.SynchronizationContextThread+SendOrPostWrapper& ret) [0x00012] in <474fc6b46f7646c587f524cda12acaf9>:0
12/25 21:42:10 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 61 Threads
12/25 21:42:19 Trace: Successful POST response from https://push.roonlabs.com/push/1/connect
12/25 21:42:25 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 62 Threads
12/25 21:42:40 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 61 Threads
12/25 21:42:55 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 61 Threads
12/25 21:43:10 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 61 Threads
12/25 21:43:25 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 61 Threads
12/25 21:43:40 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 62 Threads
... ~4,500 lines skipped ...
12/26 16:35:07 Info: [stats] 6583mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 267 Threads
12/26 16:35:22 Info: [stats] 6583mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 267 Threads
12/26 16:35:37 Info: [stats] 6583mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 267 Threads
12/26 16:35:52 Info: [stats] 6583mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 267 Threads
12/26 16:36:07 Info: [stats] 6583mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 267 Threads
12/26 16:36:22 Info: [stats] 6585mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 268 Threads
12/26 16:36:37 Info: [stats] 6585mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 268 Threads
12/26 16:36:52 Info: [stats] 6585mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 268 Threads
12/26 16:37:07 Info: [stats] 6585mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 268 Threads
12/26 16:37:22 Info: [stats] 6585mb Virtual, 1865mb Physical, 892mb Managed, 0 Handles, 268 Threads
And that 21:42:10 start time from this endless [stats] update sounds like it probably corresponded to when the Roon Core stopped working last night. Hhmmm, I can upload the complete logs if you like.
So I will go ahead an change my Root DNS Servers since using the actual Core DNS Servers really isn’t appropriate for me, but it really looks like something else is going wrong …
Casey
Note: I’ve gone ahead and uploaded the current /var/roon/RoonServer/Logs/RoonServer_log.txt as “RoonServer_log-12-26.txt” since my efforts at quoting the log contents have been interpreted as web addresses. I’ll have to get better at using this forum’s text editor. Sorry!
Casey
Hey @Casey_Leedom,
Hope you had a great holiday! Thanks for posting those logs and letting me know your findings, I spoke to QA again regarding your case and the reason why we wanted you to switch over to your Router as the DNS + DHCP server is because of the squeezebox issues you reported (in case your Core can’t see it).
You posted this trace:
12/25 21:42:09 Critical: scx: System.NullReferenceException: Object reference not set to an instance of an object
at Sooloos_Broker_Api_Broker_Adapter.Serialize (System.Object obj, System.IO.Stream stream) [0x00177] in <5688c850c7ba4c9aacd47453605b5145>:0
at Sooloos.Broker.Remoting.RemotingServer._PutObject (System.Object o, System.IO.Stream stream, System.Boolean inline) [0x0010b] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.Broker.Remoting.RemotingServer+<>c__DisplayClass28_0.<OnGetService>b__0 (Base.Result`1[T] result) [0x0002b] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.Broker.Distributed.ServerConnection.OnGetService (System.Guid guid, Base.ResultCallback`1[T] cb_result) [0x0001e] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Broker.Remoting.RemotingServer.OnGetService (System.Int32 rid, System.Byte[] body) [0x0001f] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.Broker.Remoting.RemotingServer+<>c__DisplayClass22_0.<OnRequestReceived>b__0 () [0x00011] in <8fd085cf0e0246bc8dedcd28cc594fef>:0
at Sooloos.SynchronizationContextThread+<>c__DisplayClass45_0.<Post>b__0 (System.Object _) [0x00000] in <474fc6b46f7646c587f524cda12acaf9>:0
at Sooloos.SynchronizationContextThread._Dispatch (Sooloos.SynchronizationContextThread+SendOrPostWrapper& ret) [0x00012] in <474fc6b46f7646c587f524cda12acaf9>:0
12/25 21:42:10 Info: [stats] 4633mb Virtual, 1858mb Physical, 843mb Managed, 0 Handles, 61 Threads
I checked with QA what this could mean and we believe this is your machine telling Roon that the network adapter is not accessible. The endless [stats] you’re seeing are normal traces, those just report current RAM usage and thread counts so I would not be too worried about those but look for the trace immediately before that (the adapter failing to be discovered).
Moving forward, I think we should try to simplify & rebuild - Please try hosting your DNS + DHCP features on your router instead of on the machine (even temporarily) to see if this helps. I am not sure if you have had a chance yet, but I would also verify how the setup performs if you temporarily host the Core on another machine, at least that would give us some better ideas of what to check, weather it be the network or the machine itself. Please let me know your findings when possible!
Thanks,
Noris
I’ll start the experiments. It’ll be pretty easy to swap the DNS. I just put the Comcast DNS servers cdns01.comcast.net and cdns02.comcast.net in my db.root bind configuration file. Hsting the Roon Core on another machine would be a bit more of a challenge since the Audio Files are on an 8TB drive in the server Hypatia.
Casey
You could spin up a SMB server daemon on Hypatia, move the Core to another machine (remembering to follow the migration instructions in the Roon KB), and point the Core in the new machine to the shared SMB folder in Hypatia containing your music.
Thanks @Fernando_Pereira!
I’ll focus on the DNS issues since they’re so much easier to experiment with for the nonce.
I am concerned about a couple of issues with regard to that however:
Just because the Roon Core gets a transient DNS failure shouldn’t cause it to require a restart. Throwing a warning or even an error, okay. But to stop working is a bit too much.
I’ve noticed that the “normal” messages about:
12/28 11:55:57 Info: [stats] 7986mb Virtual, 2167mb Physical, 972mb Managed, 0 Handles, 845 Threads
seems to show ever increasing values for all of these things. That sort of feels like a leak …
Casey
Hey @Casey_Leedom,
I just wanted to check in with you here and see if there were any changes since your last message. I have noted your findings as a note with your case but the best way forward would be to verify if the same behavior occurs on another machine and if the DNS is being hosted on your router instead of the current machine.
Have you by any chance tried switching the Core over to another machine or tried changing the DNS and are experiencing the same issues? Please let me know when possible.
Thanks,
Noris
Sorry for the delay in responding. Work gets in the way of life. Today I’m going to a friend’s father’s Mass, but tomorrow I’ll have time to sit down and do some extensive testing and provide a comprehensive update.
Casey
Hey @Casey_Leedom,
No rush at all, I definitely understand that life can get busy sometimes.
Whenever you’re ready to pick this up again just let me know on this thread.
Thanks,
Noris
Okay, starting an extended debugging session today. Hopefully I’ll be able to narrow down on what’s going wrong. I’ll probably send a sequence of messages out rather than a single massive update.
First, DNS:
However:
1m accounts5.roonlabs.com 5m bits.roonlabs.net 5m devicedb.roonlabs.net 5m identifier.roonlabs.net 5m imagecache.roonlabs.net 5m metadataserver.roonlabs.net 5m push.roonlabs.com 5m updates.roonlabs.com
1019 accounts5.roonlabs.com 450 bits.roonlabs.net 75 devicedb.roonlabs.net 2293 identifier.roonlabs.net 19 imagecache.roonlabs.net 4672 metadataserver.roonlabs.net 784 push.roonlabs.com 26 updates.roonlabs.com
Okay, on to more debugging …
Casey
Okay, next stage of debugging. I’ve replaced my /etc/.bin.db.root with the following:
root@hypatia:~ cat /etc/bind/db.root ; Comcast DNS Servers which are probably more reliable than the actual ; Root Servers given the load and prominance of the Root Servers. ; . 3600000 NS cdns01.comcast.net. cdns01.comcast.net. 3600000 A 75.75.75.75 . 3600000 NS cdns02.comcast.net. cdns02.comcast.net. 3600000 A 75.75.76.76 root@hypatia:~
So unless we think their DNS servers are overloaded, we’re good.
I stop/started the Roon Server and started playing the song Something to Shout About: You’d Be So Nice to Come Home To by Ben Webster in DSD256/DSF. It ticked along for 3:59mm:ss before stalling out. The Roon Server Log file at that point showed:
... 01/06 12:44:52 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:04/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:44:57 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:09/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:00 Info: [stats] 4833mb Virtual, 1744mb Physical, 982mb Managed, 0 Handles, 66 Threads 01/06 12:45:02 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:14/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:08 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:20/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:13 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:25/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:15 Info: [stats] 4843mb Virtual, 1755mb Physical, 996mb Managed, 0 Handles, 65 Threads 01/06 12:45:18 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:31/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:23 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:35/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:28 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:40/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:30 Info: [stats] 4856mb Virtual, 1768mb Physical, 1007mb Managed, 0 Handles, 65 Threads 01/06 12:45:34 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [100% buf] [PLAYING @ 3:46/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:37 Trace: [prebuffer] short read: 0 / 2257920 fill=14055552 01/06 12:45:39 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [83% buf] [PLAYING @ 3:51/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:44 Trace: [Living Room] [HighQuality 6.0x, DSD256 DSF => 24/88] [25% buf] [PLAYING @ 3:56/4:24] Something to Shout About: You'd Be So Nice to Come Home To - Ben Webster 01/06 12:45:45 Info: [stats] 4641mb Virtual, 1554mb Physical, 726mb Managed, 0 Handles, 64 Threads
And at that point, the Roon Server seemed to spontaneously restart since it rotated the log files. And then rotated them again. I’m leaving it this way for a bit while I go out and grab lunch. As far as I can see, the “[prebuffer] short read” message seemed to be right at the point where it went south.
Casey
Hello @Casey_Leedom,
Thanks for providing that information. I have re-added your case to be discussed with the devs later this week and will let you know what they say regarding your comments. Would it be possible for you to re-upload the full log set to our servers as you have done before in case the devs want to take another look after your most recent findings?
Thanks,
Noris
Sure! I’ll do that tonight when I get back from work/the gym!
Casey
As usual, when one tries to break things they don’t cooperate. So far no failures tonight. I’ll keep trying.
Casey
(sigh) Now the Roon Server is spontaneously rebooting without any notes added to the RoonServer_log.txt explaining why:
root@hypatia:/var/roon/RoonServer/Logs ls -ltr
total 21664
-rw-r--r-- 1 root root 78503 Jan 8 17:34 RoonServer_log.20.txt
-rw-r--r-- 1 root root 335516 Jan 8 18:19 RoonServer_log.19.txt
-rw-r--r-- 1 root root 29365 Jan 8 18:20 RoonServer_log.18.txt
-rw-r--r-- 1 root root 3972563 Jan 10 18:47 RoonServer_log.17.txt
-rw-r--r-- 1 root root 569892 Jan 10 19:04 RoonServer_log.16.txt
-rw-r--r-- 1 root root 1169834 Jan 10 19:08 RoonServer_log.15.txt
-rw-r--r-- 1 root root 7231699 Jan 10 19:38 RoonServer_log.14.txt
-rw-r--r-- 1 root root 1306516 Jan 10 20:42 RoonServer_log.13.txt
-rw-r--r-- 1 root root 1191959 Jan 12 17:12 RoonServer_log.12.txt
-rw-r--r-- 1 root root 266402 Jan 12 20:36 RoonServer_log.11.txt
-rw-r--r-- 1 root root 1651628 Jan 12 20:40 RoonServer_log.10.txt
-rw-r--r-- 1 root root 1473561 Jan 15 06:36 RoonServer_log.09.txt
-rw-r--r-- 1 root root 2071287 Jan 15 16:27 RoonServer_log.08.txt
-rw-r--r-- 1 root root 257589 Jan 15 16:34 RoonServer_log.07.txt
-rw-r--r-- 1 root root 58371 Jan 15 16:56 RoonServer_log.06.txt
-rw-r--r-- 1 root root 27306 Jan 15 16:57 RoonServer_log.05.txt
-rw-r--r-- 1 root root 68866 Jan 15 17:13 RoonServer_log.04.txt
-rw-r--r-- 1 root root 68607 Jan 15 17:20 RoonServer_log.03.txt
-rw-r--r-- 1 root root 149526 Jan 15 17:26 RoonServer_log.02.txt
-rw-r--r-- 1 root root 94897 Jan 15 17:32 RoonServer_log.01.txt
-rw-r--r-- 1 root root 48337 Jan 15 17:36 RoonServer_log.txt
root@hypatia:/var/roon/RoonServer/Logs tail RoonServer_log.01.txt
01/15 17:32:00 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:19/4:15] Circles - Ace of Cups
01/15 17:32:01 Info: [stats] 4960mb Virtual, 1984mb Physical, 1315mb Managed, 0 Handles, 68 Threads
01/15 17:32:05 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:25/4:15] Circles - Ace of Cups
01/15 17:32:11 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:30/4:15] Circles - Ace of Cups
01/15 17:32:16 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:35/4:15] Circles - Ace of Cups
01/15 17:32:16 Info: [stats] 4965mb Virtual, 1990mb Physical, 1319mb Managed, 0 Handles, 68 Threads
01/15 17:32:21 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:41/4:15] Circles - Ace of Cups
01/15 17:32:26 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:46/4:15] Circles - Ace of Cups
01/15 17:32:31 Info: [stats] 4972mb Virtual, 1997mb Physical, 1323mb Managed, 0 Handles, 66 Threads
01/15 17:32:32 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:51/4:15] Circles - Ace of Cups
root@hypatia:/var/roon/RoonServer/Logs head RoonServer_log.txt
01/15 17:32:37 Info: Starting RoonServer v1.5 (build 363) stable on linuxx64
01/15 17:32:37 Trace: Checking if we are already running
01/15 17:32:37 Trace: Nope, we are the only one running
01/15 17:32:37 Info: Is 64 bit? True
01/15 17:32:38 Info: Command Line Argument: -watchdogport=34131
01/15 17:32:38 Trace: [childprocess] using .NET child process
01/15 17:32:38 Trace: [realtime] fetching time from NTP server
01/15 17:32:38 Info: [broker] starting 73f38150-87f2-4715-be58-6b4a28ba13f9
01/15 17:32:38 Trace: [realtime] Got time from NTP: 1/16/2019 1:32:38 AM (3756591158132ms)
01/15 17:32:38 Trace: [realtime] Updated clock skew to -00:00:00.0465280 (-46.528ms)
The iPhone Roon App takes forever to connect to the Roon Server (and often never manages a connection). Here’s some of the weirdness in the Roon Server Log File for that:
...
01/15 17:38:09 Info: [stats] 3992mb Virtual, 1733mb Physical, 1124mb Managed, 0 Handles, 55 Threads
01/15 17:38:24 Info: [stats] 3992mb Virtual, 1734mb Physical, 1124mb Managed, 0 Handles, 55 Threads
01/15 17:38:24 Info: [brokerserver] Client connected: 10.13.100.101:52248
01/15 17:38:24 Trace: [SOOD] Adding User IP 10.13.100.101
01/15 17:38:24 Trace: [raat] [sood] Refreshing device list
01/15 17:38:24 Trace: [raatserver] [sood] Refreshing device list
01/15 17:38:25 Trace: [raat] RAATServer discovered: RaatServer Caseys-iPhone @ 10.13.100.101:52249
01/15 17:38:25 Info: [raatserver] GOT SERVER 310b8912-db7b-48d4-95f3-5997b7bc23e7::719e7074-d1a6-4e8c-8f6d-d5249eb052c8 @ 10.13.100.101:52249 Caseys-iPhone PROTOVER=1 RAATVER=1.1.30
01/15 17:38:25 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
01/15 17:38:25 Trace: [push] retrying connection in 69736ms
01/15 17:38:25 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52249] connecting (attempt 1)
01/15 17:38:25 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52249] connected
01/15 17:38:25 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
01/15 17:38:25 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "default", "name": "Casey's iPhone", "type": "ios", "vendor": "Apple", "is_system_output": true, "model": "iPhone8,2", "auto_enable": true, "auto_name": "Casey's iPhone", "discovery_data": {"model": "N/A", "unique_id": "510aec0c-03e2-d5da-efa1-31bacd997689", "tcp_port": 52247, "protocol_version": "3", "version": "N/A", "raat_version": "1.1.30", "vendor": "N/A"}, "config": {"external_config": {"is_private": true}, "output": {"type": "ios", "device": "default", "name": "Casey's iPhone"}, "volume": {"type": "ios", "device": "default"}, "unique_id": "510aec0c-03e2-d5da-efa1-31bacd997689"}}]}
01/15 17:38:25 Info: [devicedb] [autodetect] Match DeviceAutodetectData[Type=Local Vendor=Apple Model=iPhone8,2] => Apple iPhone
01/15 17:38:25 Info: [raatserver] GOT DEVICE 719e7074-d1a6-4e8c-8f6d-d5249eb052c8::default Type=ios Name=Casey's iPhone Vendor=Apple
01/15 17:38:25 Trace: SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=73f38150-87f2-4715-be58-6b4a28ba13f9 BrokerName='hypatia' }
01/15 17:38:25 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"default","subscription_id":"1"}
01/15 17:38:25 Info: [raatserver] [Casey's iPhone] connecting (attempt 1)
01/15 17:38:25 Trace: SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=100500363 DisplayValue='1.5 (build 363) stable' Branch='stable' } }
01/15 17:38:25 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
01/15 17:38:25 Trace: [Casey's iPhone] [raatclient] Initializing RAAT session
Or:
01/15 17:28:46 Info: [stats] 4657mb Virtual, 1882mb Physical, 1235mb Managed, 0 Handles, 65 Threads
01/15 17:28:50 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:05/2:56] Fantasy 1&4 - Ace of Cups
01/15 17:28:55 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:11/2:56] Fantasy 1&4 - Ace of Cups
01/15 17:28:57 Info: [brokerserver] Client disconnected: 10.13.100.101:52237
01/15 17:28:57 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
01/15 17:28:57 Trace: [push] retrying connection in 14505ms
01/15 17:28:57 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] lost client connection. Retrying
01/15 17:28:57 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] connecting (attempt 1)
01/15 17:28:57 Info: [transport] destroyed zone Casey's iPhone was playing? False
01/15 17:28:57 Trace: [zone Casey's iPhone] Suspend
01/15 17:28:57 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
01/15 17:28:57 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] client connection failed. Retrying in 500ms
01/15 17:28:57 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] connecting (attempt 2)
01/15 17:28:58 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
01/15 17:28:58 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] client connection failed. Retrying in 750ms
01/15 17:28:58 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] connecting (attempt 3)
01/15 17:28:58 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
01/15 17:28:58 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] client connection failed. Retrying in 1125ms
01/15 17:28:59 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] connecting (attempt 4)
01/15 17:29:00 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
01/15 17:29:00 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] client connection failed. Retrying in 1687ms
01/15 17:29:00 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:15/2:56] Fantasy 1&4 - Ace of Cups
01/15 17:29:01 Info: [stats] 4663mb Virtual, 1889mb Physical, 1240mb Managed, 0 Handles, 63 Threads
01/15 17:29:01 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] connecting (attempt 5)
01/15 17:29:01 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
01/15 17:29:01 Trace: [raatserver] [RaatServer Caseys-iPhone @ 10.13.100.101:52242] client connection failed. Giving up
01/15 17:29:01 Trace: [raat] [sood] Refreshing device list
01/15 17:29:06 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:21/2:56] Fantasy 1&4 - Ace of Cups
01/15 17:29:07 Trace: Successful POST response from https://push.roonlabs.com/push/1/connect
01/15 17:29:07 Trace: [push] connecting to 35.231.98.0:9200
01/15 17:29:07 Trace: [push] connected
01/15 17:29:11 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:27/2:56] Fantasy 1&4 - Ace of Cups
01/15 17:29:16 Trace: [Living Room] [Lossless, 16/44 FLAC => 16/44] [100% buf] [PLAYING @ 0:32/2:56] Fantasy 1&4 - Ace of Cups
01/15 17:29:16 Info: [stats] 4870mb Virtual, 1895mb Physical, 1244mb Managed, 0 Handles, 68 Threads
Why is the Roon Server trying to connect to my iPhone??!?!?! Weird.
In any case, things are basically unusable at this point. When I can get the server to play it does so for a few minutes and then the Roon Server spontaneously restarts.
Casey
Well, it worked for nearly an hour before it stopped responding. Here’s where it was:
...
01/15 19:22:45 Info: [stats] 4811mb Virtual, 1626mb Physical, 919mb Managed, 0 Handles, 70 Threads
01/15 19:22:46 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [100% buf] [PLAYING @ 3:42/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:22:51 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [100% buf] [PLAYING @ 3:46/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:22:56 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [100% buf] [PLAYING @ 3:52/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:23:00 Info: [stats] 4826mb Virtual, 1641mb Physical, 933mb Managed, 0 Handles, 70 Threads
01/15 19:23:01 Trace: [prebuffer] short read: 0 / 19200 fill=956072
01/15 19:23:01 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [98% buf] [PLAYING @ 3:57/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:23:07 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [27% buf] [PLAYING @ 4:02/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:23:09 Trace: [squeezebox/client] [10.13.100.30:36503] unhandled command: DSCO
00000000: 00 .
01/15 19:23:13 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [9% buf] [PLAYING @ 4:09/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:23:15 Info: [stats] 4834mb Virtual, 1649mb Physical, 941mb Managed, 0 Handles, 69 Threads
01/15 19:23:18 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [9% buf] [PLAYING @ 4:14/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:23:21 Trace: [squeezebox/client] [10.13.100.30:36503] GOT STAT event_code=STMd crlf_count=0 mas_initialized=^@ mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=65535 jiffies=1473656536 output_buffer_size=3528000 output_buffer_fullness=3305848 elapsed_seconds=258 voltage=0 elapsed_milliseconds=258037 server_timestamp=0 error_code=0
01/15 19:23:23 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [9% buf] [PLAYING @ 4:20/4:22] Simple Twist of Fate [Take 3, Remake] - Bob Dylan
01/15 19:23:26 Trace: [squeezebox/client] [10.13.100.30:36503] GOT STAT event_code=STMu crlf_count=0 mas_initialized=^@ mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=65535 jiffies=1473660898 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=262 voltage=0 elapsed_milliseconds=262354 server_timestamp=0 error_code=0
01/15 19:23:26 Info: [zoneplayer/squeezebox] Squeezebox Touch (Squeezebox Touch# 00:04:20:23:35:35 @ 10.13.100.30:36503) reporitng natural end due to STMu
01/15 19:23:26 Info: [zone Living Room] OnPlayFeedback StoppedEndOfMediaNatural
01/15 19:23:26 Debug: [zone Living Room] _Advance
01/15 19:23:26 Info: [library] recorded play for profile d14062e2-fa57-49d5-8a3b-c690e9180b4a: mediaid=50:1:e54e9df3-365d-49c8-a595-1e620aa6cd5c metadataid=123:0:MT0055935625 contentid= libraryid=50:1:e54e9df3-365d-49c8-a595-1e620aa6cd5c
01/15 19:23:26 Trace: [zone Living Room] queue got oversized. trimming 1 items from start
01/15 19:23:26 Debug: [zone Living Room] Remove(1 items, for_replace=False)
01/15 19:23:26 Info: after removeall ordered count 5000 shuffle count 5000
01/15 19:23:26 Trace: [library] finished with 1776 dirty tracks 74 dirty albums 197 dirty performers 620 dirty works 1197 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 2054 changed objects
01/15 19:23:26 Trace: [metadatasvc] REQ https://metadataserver.roonlabs.net/md/4/updatemetadata?uid=9e427f86-038c-4631-8512-6883e202c9fc&lid=&token=d81a29a1-7895-4908-8a35-9c91226f6da1&metadataid[]=7b004d5430303535393335363235&metadataid[]=79004d5730303033323131373536
01/15 19:23:26 Debug: [library/index] updating search indices: 34 ops 0 adds, 0 removes
01/15 19:23:26 Trace: [Living Room] [Lossless, 24/96 FLAC => 24/96] [9% buf] [LOADING @ 0:00] Straight To Helen - Bobbi Staff
01/15 19:23:26 Trace: [squeezebox/server] [COMET] [{"channel":"/0b62ed89/slim/playerstatus/00:04:20:23:35:35","id":"304","data":{"alarm_timeout_seconds":3600,"seq_no":73,"alarm_state":"none","alarm_next":0,"preset_data":[{},{},{},{},{},{},{},{},{},{}],"playlist shuffle":0,"preset_loop":[0,0,0,0,0,0,0,0,0,0],"playlist mode":"off","mode":"play","remote":1,"player_connected":1,"mixer volume":77,"playlist repeat":0,"signalstrength":0,"power":1,"player_name":"Squeezebox Touch","digital_volume_control":1,"player_ip":"10.13.100.30:36503","alarm_snooze_seconds":54,"playlist_tracks":1,"item_loop":[{"text":"Straight To Helen\nBobbi Staff","trackType":"local","album":"RCA Singles","track":"Straight To Helen","artist":"Bobbi Staff","style":"itemplay","icon-id":"26044","params":{"track_id":26238258,"playlist_index":0}}],"count":1,"base":{"actions":{}}}}]
01/15 19:23:26 Debug: [query] Sooloos.Broker.Transport.TransportItem: 5001 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
01/15 19:23:26 Debug: [query] Sooloos.Broker.Transport.TransportItem: 5001 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
01/15 19:23:26 Debug: [query] Sooloos.Broker.Transport.TransportItem: 5001 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
01/15 19:23:26 Debug: [query] Sooloos.Broker.Transport.TransportItem: 5001 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
01/15 19:23:26 Trace: [library] endmutation in 93ms
01/15 19:23:26 Trace: [metadatasvc] GOT (493ms) Sooloos.Msg.Metadata.UpdateMetadataResponse:
01/15 19:23:26 Critical: scx: System.NullReferenceException: Object reference not set to an instance of an object
at Sooloos.Metadata.Proxy+<>c__DisplayClass24_0.<UpdateMetadata>b__0 () [0x00063] in <364c3707ba084cecaf0256f764915d8d>:0
at Sooloos.Metadata.Proxy+<>c__DisplayClass24_0.<UpdateMetadata>b__2 (Base.Result`1[T] result) [0x00023] in <364c3707ba084cecaf0256f764915d8d>:0
at Sooloos.Metadata.Proxy+<>c__DisplayClass12_0`1[T].<_LogResult>b__0 (Base.Result`1[T] result) [0x00151] in <364c3707ba084cecaf0256f764915d8d>:0
at Sooloos.HttpClient+<>c__DisplayClass4_0`2[F,T].<_MakeConversionCallback>b__0 (Base.Result`1[T] result) [0x0004a] in <474fc6b46f7646c587f524cda12acaf9>:0
at Sooloos.HttpClient+<>c__DisplayClass8_3.<GET>b__4 () [0x00020] in <474fc6b46f7646c587f524cda12acaf9>:0
at Sooloos.CallingThread+<>c__DisplayClass12_0.<Post>b__1 (System.Object <p0>) [0x00000] in <474fc6b46f7646c587f524cda12acaf9>:0
at Sooloos.SynchronizationContextThread._Dispatch (Sooloos.SynchronizationContextThread+SendOrPostWrapper& ret) [0x00012] in <474fc6b46f7646c587f524cda12acaf9>:0
01/15 19:23:30 Info: [stats] 4848mb Virtual, 1664mb Physical, 962mb Managed, 0 Handles, 69 Threads
01/15 19:23:45 Info: [stats] 4848mb Virtual, 1664mb Physical, 962mb Managed, 0 Handles, 60 Threads
01/15 19:24:00 Info: [stats] 4848mb Virtual, 1664mb Physical, 962mb Managed, 0 Handles, 61 Threads
... [[ The above Virtual/Physical/Managed/Handle/Threads info line repeated forever after ]] ...
It appears to have stopped right about where the infinite status messages started …
Casey