Android Roon Remote looses connection to Core (daily)

CRo · February 15, 2019, 9:48am

Hi @noris,

These are the error messages on the Android devices (same for both the Android 6.0.1 and Android 5.0):

Initially this screen is shown:

Shortly thereafter this screen is shown:

The last screen stays indefinitely (until quitting/killing/switching away from the Roon app.)

Restarting the Android app (by simply going back to the Android desktop and selecting the App icon again) does not help.
Android Settings: Apps: Roon: Force Stop does not help.
Rebooting the Android phone does not change this.

Another idea:

Android Settings: Apps: Roon: Uninstall, then Playstore: Roon: Install: “I Agree” to Roon Terms and Conditions: The following screen is then displayed:

The app does not progress past that screen.

The above steps have been attempted today (15.02.), local (log) time is 10:32 right now.

The status of the Roon service:

[root@grendel Logs]# date
Fri Feb 15 10:34:55 CET 2019

[root@grendel Logs]# systemctl -l status roonserver
● roonserver.service - RoonServer
   Loaded: loaded (/etc/systemd/system/roonserver.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2019-02-12 09:04:23 CET; 3 days ago
 Main PID: 17917 (start.sh)
    Tasks: 80
   CGroup: /system.slice/roonserver.service
           ├─17917 /bin/bash /opt/RoonServer/start.sh
           ├─17921 /opt/RoonServer/RoonMono/bin/RoonServer --debug --gc=sgen --server RoonServer.exe
           ├─17932 /pool/opt/RoonServer/RoonMono/bin/RoonAppliance --debug --gc=sgen --server RoonAppliance.exe -watchdogport=44210
           ├─17939 /pool/opt/RoonServer/Server/processreaper 17932
           └─18022 /pool/opt/RoonServer/RoonMono/bin/RAATServer --debug --gc=sgen --server RAATServer.exe

Feb 13 11:15:37 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 2456 samples mf=0x7f2f9c0386d0 underlying_objecttype=2 underlying_sfidx=4
Feb 13 11:15:38 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 2916 samples mf=0x7f2fac00cdb0 underlying_objecttype=2 underlying_sfidx=4
Feb 13 11:15:38 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 5198 samples mf=0x7f2f480561e0 underlying_objecttype=2 underlying_sfidx=4
Feb 13 11:15:38 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 4441 samples mf=0x7f2f8c08e600 underlying_objecttype=2 underlying_sfidx=4
Feb 13 11:15:39 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 2908 samples mf=0x7f2fa4003740 underlying_objecttype=2 underlying_sfidx=4
Feb 13 11:15:40 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 15443 samples mf=0x7f2fb01aa5b0 underlying_objecttype=2 underlying_sfidx=4
Feb 13 11:15:40 grendel.home start.sh[17917]: [AAC/oop] GOT 44100/24/2 3763 samples mf=0x7f2f98004650 underlying_objecttype=2 underlying_sfidx=4
Feb 13 22:57:18 grendel.home start.sh[17917]: System.Net.Sockets.SocketException (0x80004005): Connection reset by peer
Feb 13 22:57:18 grendel.home start.sh[17917]: at System.Net.Sockets.Socket.EndReceive (System.IAsyncResult asyncResult) [0x00012] in <126998f2e5ae42fe95554117eb649feb>:0
Feb 13 22:57:18 grendel.home start.sh[17917]: at Sooloos.RnetJsonClient+<>c__DisplayClass65_0.<_BeginRead>b__0 (System.IAsyncResult ar) [0x00046] in <7f0a74b68d2a4a0ba3084b62b8028591>:0

We see that the Roon core has been running for three days:

Active: active (running) since Tue 2019-02-12 09:04:23 CET; 3 days ago

I will now stop and start the Roon service:

[root@grendel Logs]# date
Fri Feb 15 10:37:40 CET 2019
[root@grendel Logs]# systemctl -l stop roonserver
[root@grendel Logs]# systemctl -l start roonserver
[root@grendel Logs]# systemctl -l status roonserver
● roonserver.service - RoonServer
   Loaded: loaded (/etc/systemd/system/roonserver.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2019-02-15 10:38:03 CET; 4s ago
 Main PID: 7127 (start.sh)
    Tasks: 56
   CGroup: /system.slice/roonserver.service
           ├─7127 /bin/bash /opt/RoonServer/start.sh
           ├─7131 /opt/RoonServer/RoonMono/bin/RoonServer --debug --gc=sgen --server RoonServer.exe
           ├─7142 /pool/opt/RoonServer/RoonMono/bin/RoonAppliance --debug --gc=sgen --server RoonAppliance.exe -watchdogport=42142
           ├─7149 /pool/opt/RoonServer/Server/processreaper 7142
           └─7242 /pool/opt/RoonServer/RoonMono/bin/RAATServer --debug --gc=sgen --server RAATServer.exe

Feb 15 10:38:03 grendel.home systemd[1]: Started RoonServer.
Feb 15 10:38:03 grendel.home start.sh[7127]: 00:00:00.001 Trace: [childprocess] using unix child process
Feb 15 10:38:03 grendel.home start.sh[7127]: Initializing
Feb 15 10:38:03 grendel.home start.sh[7127]: Started
Feb 15 10:38:04 grendel.home start.sh[7127]: aac_fixed decoder found, checking libavcodec version...
Feb 15 10:38:04 grendel.home start.sh[7127]: has mp3float: 1, aac_fixed: 0

We see that the Roon core has been freshly started:

Active: active (running) since Fri 2019-02-15 10:38:03 CET; 4s ago

No we start the Android App (on the STV100-1 phone, which where it was uninstalled and re-installed as documented above.)

Success!!

The Android app finds the core:

Now, what we can do is to watch what happens in the next 12 to 24 hours when the Android devices will eventually fail to connect again.

I’m happy to help out. Let me know what I can test for you.

-Chris

evand · February 16, 2019, 6:36am

I sincerely hope that this gets resolved soon. I’ve reported it on more than one occasion and it’s pretty much been ignored up till now.

CRo · February 16, 2019, 11:54am

Well, @Noris has said Roon are looking at it, and I will do anything to help. I’ve been working in IT for 30 years, and am doing my best to think along.

We have a very interesting error constellation right now.

Since documenting the logs in detail yesterday at about 10:38AM, it’s now a day later.

The current status is:

The SM-N9005 phone is now unable to connect to the core again, as has been documented previously. So, nothing new.
The SM-N9005 has streaming off (as previously documented).

02/16 11:16:06 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
02/16 11:16:06 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] lost client connection. Retrying
02/16 11:16:06 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] connecting (attempt 1)
02/16 11:16:06 Info: [stats] 2769mb Virtual, 594mb Physical, 186mb Managed, 0 Handles, 61 Threads
02/16 11:16:16 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] client connection failed. Retrying in 500ms
02/16 11:16:16 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] connecting (attempt 2)
02/16 11:16:21 Info: [stats] 2769mb Virtual, 594mb Physical, 186mb Managed, 0 Handles, 59 Threads
02/16 11:16:23 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
02/16 11:16:23 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] client connection failed. Retrying in 750ms
02/16 11:16:24 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] connecting (attempt 3)
02/16 11:16:24 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
02/16 11:16:24 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] client connection failed. Retrying in 1125ms
02/16 11:16:25 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] connecting (attempt 4)
02/16 11:16:25 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
02/16 11:16:25 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] client connection failed. Retrying in 1687ms
02/16 11:16:27 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] connecting (attempt 5)
02/16 11:16:27 Warn: [rnet/RnetJsonClient] failed to connect Connection refused
02/16 11:16:27 Trace: [raatserver] [RaatServer SM-N9005 @ 192.168.0.228:46586] client connection failed. Giving up
02/16 11:16:27 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
02/16 11:16:27 Trace: [push] retrying connection in 79564ms

HOWEVER, at the same time right now the The STV100-1 phone Roon app is still functioning.

This STV100-1 device had the the Roon app in the foreground as it was put into the charging station last night.
The STV100-1 had the Roon app still in the foreground when I took it off the charger this morning.
STV100-1 was (when it was put in the charger last night) acting as remote for a Squeezebox Radio, and that still functions right now.
STV100-1 has streaming on.

Something that I don’t understand: looking at the Core logs, I am NOT seeing the string “STV100-1” right now when I’m using the STV100-1 as a remote. The log entries when the STV100-1 is in use right now look different.

TEST: I am going to select a new album to play on the SB Radio, using the STV100-1 in its capacity as a remote (this is the setup as it has been since last night when I put it in the charger.)
Currentlyplaying is Holst: The Planets, Mars, the bringer of war.

[xtian@grendel ~]$ date
Sat Feb 16 12:24:24 CET 2019

(I’m going to select Björk, Debut, Human Behvaiour):

02/16 12:25:05 Trace: [music/query] performing album query
02/16 12:25:05 Trace: [music/query] query returned 35 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:05 Debug: GET /image/kaaaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/yhdaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/gmdaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/whdaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/hmdaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/mmdaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/srdaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/ardaaaaa.256.jpg
02/16 12:25:05 Debug: GET /image/haaaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/btfaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/vkdaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/agfaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/bidaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/jrdaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/yqdaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/iqaaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/pkhaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/lneaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/vmgaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/uieaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/wtdaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/xaaaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/ccgaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/omeaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/kvdaaaaa.256.jpg
02/16 12:25:06 Debug: GET /image/uwcaaaaa.256.jpg
02/16 12:25:06 Info: [stats] 2781mb Virtual, 604mb Physical, 166mb Managed, 0 Handles, 59 Threads
02/16 12:25:16 Info: [library/performerdetails] Created performer details screen for LibraryPerformer[216954, Björk]
02/16 12:25:16 Info: [library/performerdetails] 7a004d4e30303030373639343434, 5e01dddec5871d37534a9f7f80522fb7f3cb, 7a004d4e30303033373433313338, a7003136393932, c9003237393430
02/16 12:25:16 Trace: [dbperf] flush 0 bytes, 0 ops in 10 ms (cumulative 34417052 bytes, 14934 ops in 5661 ms)
02/16 12:25:16 Trace: [music/query] performing album query
02/16 12:25:16 Trace: [music/query] query returned 3 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:16 Trace: [music/query] performing album query
02/16 12:25:16 Trace: [music/query] query returned 1 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:16 Trace: [music/query] performing album query
02/16 12:25:16 Trace: [music/query] query returned 2 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:16 Trace: [music/query] performing album query
02/16 12:25:16 Trace: [music/query] query returned 0 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:16 Trace: [geoip] GET https://accounts5.roonlabs.com/geoip/1/lookup
02/16 12:25:16 Debug: GET /image/iqaaaaaa.1024.jpg
02/16 12:25:16 Debug: GET /image/skdaaaaa.256.jpg
02/16 12:25:16 Debug: GET /image/cffaaaaa.256.jpg
02/16 12:25:16 Debug: GET /image/pjfaaaaa.256.jpg
02/16 12:25:16 Trace: [geoip] GOT --EDITED--,"status":"Success"}
02/16 12:25:18 Info: [library/albumdetails] Created album details screen for LibraryAlbum[126511, Björk - Debut]
02/16 12:25:18 Info: [library/albumdetails] 79004d5730303030303935323932, 79004d5230303034393332333837, 79004d5230303034333836313638, 79004d5230303033373036363739, 79004d5230303030383835373738, 79004d5230303031313930353630, 79004d5230303030383131323133, 79004d5230303030373237363538, 79004d5230303030363232333836, 79004d5230303030343632373934, 79004d5230303030343631303734, 79004d5230303030323335323036, 79004d5230303030303337393630, 79004d5230303033343630393232, 79004d5230303031323930333238, 79004d5230303034333336343030, 79004d5230303033383830323539, 79004d5230303033393631363934, 79004d5230303031323831343838, 79004d5230303034353130313138, 79004d5230303032393530313932, 79004d5230303032393530313431, 79004d5230303031323838303930, 79004d5230303031313739363433, 79004d5230303030383835383534, 79004d5230303033353033333036, 79004d5230303032393432393237, 79004d5230303032393432383537, 79004d5230303031323836383137, 79004d5230303031323832323434, 79004d5230303031323832303838, 79004d5230303031323832303837, 79004d5230303031323831383836, 79004d5230303031313832383534, 79004d5230303031313832373136, 79004d5230303031313832363732, 79004d5230303031313832343830, 3e01383b1b9aae95373a852d6fed0d540109, 3e01d8c8b4b83693f64d9a291684a94f99e4, 3e014535ce5996ab4342a692f7816735305b, 3e015057c838a31401448278e13f62152bbc, 3e01461a4d34c1a1b44c87ae884b405ae7b5, 3e0196969a122016403d8ba17deb3f7ccfad, 3e01a66374996b895b45a87743a15a4b6b32, 3e01da069cbce80b014e93a39a41261a8de3, 3e011bdc9d8b4d94354b82763cd8177e7732, 3e0100b54539031e603089a282b0938d8397, 3e01e3799019f4b7d337b6d89733042a798e, 3e01e4d869d0f468d835b96e6ec490495cd6, 3e013317140165eaa74c87fc81ae3ca72d59, 3e01d95502ed58a8af4d93c1ac75893f86da, a6003333333338353530, a6003930303931343731, a6003336323631323832, c80030303735353936313436383639, c800736c333879327a3232366b7463, c80035303136393538303230363230, c80030303733313435323133323332, c80030303630303735333033343137
02/16 12:25:18 Trace: [music/query] performing album query
02/16 12:25:18 Trace: [music/query] query returned 3 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:18 Trace: [music/query] performing album query
02/16 12:25:18 Trace: [music/query] query returned 1 Sooloos.Broker.Api.AlbumLite(s)
02/16 12:25:18 Debug: GET /image/skdaaaaa.1024.jpg
02/16 12:25:20 Trace: [zone Kitchen] Playing 11 Items
02/16 12:25:20 Trace: [zone Kitchen] Selecting Source state=Paused
02/16 12:25:20 Trace: [zone Kitchen] Playing TransportItem
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] SENT strm command=q autostart=0 formatbyte=p pcmsamplesize=1 pcmsamplerate=3 pcmchannels=2 pcmendian=1 threshold=0 spdif_enable=0 trans_period=0 trans_type=0, flags=0, output_threshold=0, replay_gain=0, http_header=
02/16 12:25:20 Trace: [zone Kitchen] Selecting Source state=Stopped
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] SENT strm command=q autostart=0 formatbyte=p pcmsamplesize=1 pcmsamplerate=3 pcmchannels=2 pcmendian=1 threshold=0 spdif_enable=0 trans_period=0 trans_type=0, flags=0, output_threshold=0, replay_gain=0, http_header=
02/16 12:25:20 Trace: [Kitchen] [HighQuality, 24/96 FLAC => 24/48] [100% buf] [LOADING @ 0:00] Human Behaviour - Björk
02/16 12:25:20 Trace: [squeezebox/server] [COMET] [{"channel":"/55dbb4b0/slim/playerstatus/00:04:20:2c:77:5c","id":"17","data":{"alarm_timeout_seconds":3600,"seq_no":4,"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":28,"playlist repeat":0,"signalstrength":0,"power":1,"player_name":"Squeezebox Radio","digital_volume_control":1,"player_ip":"192.168.0.210:58472","alarm_snooze_seconds":54,"playlist_tracks":1,"item_loop":[{"text":"The Planets, Op. 32: Mars, the bringer of war\nBuzz Ensemble, M\u00e9lanie Barney / Buzz Ensemble / Gustav Holst / Enrico O. Dastous","trackType":"local","album":"Holst: The Planets","track":"The Planets, Op. 32: Mars, the bringer of war","artist":"Buzz Ensemble / M\u00e9lanie Barney / Buzz Ensemble, M\u00e9lanie Barney","style":"itemplay","icon-id":"1157","params":{"track_id":858674,"playlist_index":0}}],"count":1,"base":{"actions":{}}}}]
02/16 12:25:20 Trace: [musicpowerstate] music is playing, preventing idle sleep
02/16 12:25:20 Trace: [squeezebox/server] [COMET] [{"channel":"/55dbb4b0/slim/playerstatus/00:04:20:2c:77:5c","id":"17","data":{"alarm_timeout_seconds":3600,"seq_no":4,"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":28,"playlist repeat":0,"signalstrength":0,"power":1,"player_name":"Squeezebox Radio","digital_volume_control":1,"player_ip":"192.168.0.210:58472","alarm_snooze_seconds":54,"playlist_tracks":1,"item_loop":[{"text":"Human Behaviour\nBj\u00f6rk","trackType":"local","album":"Debut","track":"Human Behaviour","artist":"Bj\u00f6rk","style":"itemplay","icon-id":"2306","params":{"track_id":1488434,"playlist_index":0}}],"count":1,"base":{"actions":{}}}}]
02/16 12:25:20 Info: [Kitchen] [zoneplayer] Playing: /musik/Collection/LOSLESS_IN/Björk/Debut/Björk_Debut_01_Human Behaviour.flac
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] SENT strm command=q autostart=0 formatbyte=p pcmsamplesize=1 pcmsamplerate=3 pcmchannels=2 pcmendian=1 threshold=0 spdif_enable=0 trans_period=0 trans_type=0, flags=0, output_threshold=0, replay_gain=0, http_header=
02/16 12:25:20 Info: [Kitchen] [zoneplayer] Queueing: /musik/Collection/LOSLESS_IN/Björk/Debut/Björk_Debut_02_Crying.flac
02/16 12:25:20 Trace: [roonapi] [apiclient 127.0.0.1:36318] CONTINUE Changed {"zones_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","display_name":"Kitchen","outputs":[{"output_id":"1701db671afa66cec0b33493460b16a0abd4","zone_id":"1601db671afa66cec0b33493460b16a0abd4","can_group_with_output_ids":["1701a93c0dd215dc970bb17310c699400eba","1701db671afa66cec0b33493460b16a0abd4"],"display_name":"Kitchen","volume":{"type":"number","min":0,"max":100,"value":28,"step":1,"is_muted":false,"hard_limit_min":0,"hard_limit_max":100,"soft_limit":100},"source_controls":[{"control_key":"1","display_name":"Squeezebox Radio","supports_standby":true,"status":"indeterminate"}]}],"state":"loading","is_next_allowed":true,"is_previous_allowed":true,"is_pause_allowed":true,"is_play_allowed":false,"is_seek_allowed":false,"queue_items_remaining":11,"queue_time_remaining":2899,"settings":{"loop":"disabled","shuffle":false,"auto_radio":true},"now_playing":{"seek_position":null,"length":250,"one_line":{"line1":"Human Behaviour - Bj\u00f6rk"},"two_line":{"line1":"Human Behaviour","line2":"Bj\u00f6rk"},"three_line":{"line1":"Human Behaviour","line2":"Bj\u00f6rk","line3":"Debut"},"image_key":"17f7382349b4e65c1c14f0a41a16e972","artist_image_keys":["096b929ff4d1d50131b0b2c2eb54d2c0"]}}],"zones_seek_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","queue_time_remaining":2899,"seek_position":null}]}
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMf crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=100 jiffies=5798587 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 voltage=0 elapsed_milliseconds=0 server_timestamp=0 error_code=0
02/16 12:25:20 Info: [Kitchen] [zoneplayer] Open result (Queueing): Result[Status=Success]
02/16 12:25:20 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/292 sec
02/16 12:25:20 Info: [Kitchen] [zoneplayer]     Open Result (Playing):Result[Status=Success]
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] SENT strm command=q autostart=0 formatbyte=p pcmsamplesize=1 pcmsamplerate=3 pcmchannels=2 pcmendian=1 threshold=0 spdif_enable=0 trans_period=0 trans_type=0, flags=0, output_threshold=0, replay_gain=0, http_header=
02/16 12:25:20 Info: [Kitchen] [zoneplayer] Starting playback
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] SENT strm command=s autostart=1 formatbyte=f pcmsamplesize=? pcmsamplerate=? pcmchannels=? pcmendian=? threshold=255 spdif_enable=0 trans_period=0 trans_type=0, flags=0, output_threshold=0, replay_gain=0, http_header=GET /7d194bfa1ee24491bf274a2821e71e9f HTTP/1.0


02/16 12:25:20 Info: [zone Kitchen] OnPlayFeedback Playing
02/16 12:25:20 Trace: [Kitchen] [Enhanced, 16/44 FLAC => 24/48] [100% buf] [PLAYING @ 0:00] Human Behaviour - Björk
02/16 12:25:20 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/250 sec
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMf crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=100 jiffies=5798599 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 voltage=0 elapsed_milliseconds=0 server_timestamp=0 error_code=0
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMf crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=100 jiffies=5798708 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 voltage=0 elapsed_milliseconds=0 server_timestamp=0 error_code=0
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMf crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=100 jiffies=5798719 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 voltage=0 elapsed_milliseconds=0 server_timestamp=0 error_code=0
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMf crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=100 jiffies=5798736 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 voltage=0 elapsed_milliseconds=0 server_timestamp=0 error_code=0
02/16 12:25:20 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMc crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=0 bytes_received=0 wireless_signal=100 jiffies=5798753 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 voltage=0 elapsed_milliseconds=0 server_timestamp=0 error_code=0
02/16 12:25:21 Trace: [roonapi] [apiclient 127.0.0.1:36318] CONTINUE Changed {"zones_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","display_name":"Kitchen","outputs":[{"output_id":"1701db671afa66cec0b33493460b16a0abd4","zone_id":"1601db671afa66cec0b33493460b16a0abd4","can_group_with_output_ids":["1701a93c0dd215dc970bb17310c699400eba","1701db671afa66cec0b33493460b16a0abd4"],"display_name":"Kitchen","volume":{"type":"number","min":0,"max":100,"value":28,"step":1,"is_muted":false,"hard_limit_min":0,"hard_limit_max":100,"soft_limit":100},"source_controls":[{"control_key":"1","display_name":"Squeezebox Radio","supports_standby":true,"status":"indeterminate"}]}],"state":"playing","is_next_allowed":true,"is_previous_allowed":true,"is_pause_allowed":true,"is_play_allowed":false,"is_seek_allowed":true,"queue_items_remaining":11,"queue_time_remaining":2899,"settings":{"loop":"disabled","shuffle":false,"auto_radio":true},"now_playing":{"seek_position":null,"length":250,"one_line":{"line1":"Human Behaviour - Bj\u00f6rk"},"two_line":{"line1":"Human Behaviour","line2":"Bj\u00f6rk"},"three_line":{"line1":"Human Behaviour","line2":"Bj\u00f6rk","line3":"Debut"},"image_key":"17f7382349b4e65c1c14f0a41a16e972","artist_image_keys":["096b929ff4d1d50131b0b2c2eb54d2c0"]}}]}
02/16 12:25:21 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 44100/16/2 BitRate=795 Quality=Lossless
    UpgradeBitDepth FromBitsPerSample=16 ToBitsPerSample=64 Quality=Lossless
    HeadroomGain GainDb=-3 Quality=Enhanced
    SampleRateConversion FromSampleRate=44100 ToSampleRate=48000 Algorithm=HighQuality Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Output OutputType=Squeezebox Quality=Lossless SubType= Model=Squeezebox Radio
------------------------------------------------------------
02/16 12:25:21 Trace: [roonapi] [apiclient 127.0.0.1:36318] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","queue_time_remaining":2899,"seek_position":0}]}
02/16 12:25:21 Info: [stats] 2785mb Virtual, 608mb Physical, 176mb Managed, 0 Handles, 64 Threads
02/16 12:25:22 Trace: [squeezebox/client] [192.168.0.210:58472] GOT STAT event_code=STMs crlf_count=0 mas_initialized= mas_mode=0 buffer_size=3145728 fullness=526479 bytes_received=0 wireless_signal=100 jiffies=5800452 output_buffer_size=3528000 output_buffer_fullness=1160448 elapsed_seconds=0 voltage=0 elapsed_milliseconds=38 server_timestamp=0 error_code=0
02/16 12:25:23 Trace: [roonapi] [apiclient 127.0.0.1:36318] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","queue_time_remaining":2898,"seek_position":1}]}
02/16 12:25:24 Trace: [roonapi] [apiclient 127.0.0.1:36318] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","queue_time_remaining":2897,"seek_position":2}]}
02/16 12:25:25 Trace: [roonapi] [apiclient 127.0.0.1:36318] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601db671afa66cec0b33493460b16a0abd4","queue_time_remaining":2896,"seek_position":3}]}
02/16 12:25:25 Trace: [Kitchen] [Enhanced, 16/44 FLAC => 24/48] [100% buf] [PLAYING @ 0:03/4:10] Human Behaviour - Björk

That’s alot of text.

However, I wish to draw attention to what I am not seeing in the logs:

Where is the name of the Android device? I don’t see it. It’s not there, yet I am selecting tracks on the Roon app on the STV100-1.

TEST: let’s now force-stop the Roon app.

Roon app on STV100-1 force stopped.
Started Roon app

The result:

- Roon app fails to connect to core

02/16 12:35:51 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] lost client connection. Retrying
02/16 12:35:51 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] connecting (attempt 1)
02/16 12:35:51 Info: [brokerserver] Client disconnected: 192.168.0.205:44103
02/16 12:35:51 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
02/16 12:35:51 Trace: [push] retrying connection in 48238ms
02/16 12:35:52 Info: [stats] 2797mb Virtual, 619mb Physical, 198mb Managed, 0 Handles, 61 Threads
02/16 12:36:01 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] client connection failed. Retrying in 500ms
02/16 12:36:01 Trace: Successful POST response from https://push.roonlabs.com/push/1/connect
02/16 12:36:01 Trace: [push] connecting to 35.227.82.244:9200
02/16 12:36:01 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] connecting (attempt 2)
02/16 12:36:02 Trace: [push] connected
02/16 12:36:07 Info: [stats] 2797mb Virtual, 620mb Physical, 198mb Managed, 0 Handles, 61 Threads
02/16 12:36:11 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] client connection failed. Retrying in 750ms
02/16 12:36:12 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] connecting (attempt 3)
02/16 12:36:22 Info: [stats] 2797mb Virtual, 620mb Physical, 198mb Managed, 0 Handles, 59 Threads
02/16 12:36:22 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] client connection failed. Retrying in 1125ms
02/16 12:36:23 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:44016] connecting (attempt 4)
02/16 12:36:27 Trace: [roonapi] [apiclient 127.0.0.1:36316] CONTINUE Changed {"message":"Core paired","is_error":false}
02/16 12:36:33 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:49021] client connection failed. Retrying in 1687ms
02/16 12:36:35 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:49021] connecting (attempt 5)
02/16 12:36:35 Trace: [raatserver] [RaatServer STV100-1 @ 192.168.0.205:49021] connected
02/16 12:36:35 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
02/16 12:36:35 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "default", "auto_name": "STV100-1", "auto_enable": true, "is_system_output": true, "type": "android", "name": "Default Output"}]}
02/16 12:36:35 Info: [raatserver] GOT DEVICE 8bc841a2a51e381dee84ad3dda0bd93e::default Type=android Name=Default Output 
02/16 12:36:35 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
02/16 12:36:35 Trace: [push] retrying connection in 32686ms
02/16 12:36:37 Info: [stats] 2797mb Virtual, 620mb Physical, 199mb Managed, 0 Handles, 61 Threads
02/16 12:36:45 Trace: Successful POST response from https://push.roonlabs.com/push/1/connect

VERY Interesting!

To summarize, it looks like the Android Roon app is able to live past the error that happens some time in the 12 - 24 hour period after a Roon core is newly started, so long as the app is never stopped by the Android power management features, by for example having the Roon app in running in the foreground and having the device in a charger all night.

Then, stopping and starting the Roon app causes the connection to end, and after that it can not connect to the core again, until the Roon core is restarted.

-Chris

evand · February 16, 2019, 12:20pm

Another data point - setup two ssid’s of same name and password, connect to one, then go to the other to connect there and you’ll get the same problem you’re experiencing re can’t find server.

CRo · February 16, 2019, 2:49pm

Hi evand,

I am not sure the problem has anything to do with Wifi. Or perhaps Wifi is just one part of it, because the one reliable solution to the problem is to re-start the Roon core – not to make any changes to the Android device, the wireless AP, the switch, the router, nor the Linux server. The network stays untouched.

Ofcourse, probably every single Android device we’ve ever connected to a network did so via Wifi, so it’s not possible to be certain if that has anything to do with it.

Here are some ideas to be more certain about the role various networking components play in the problem:

use a USB ethernet adapter to connect an Android device to the network. We thus cut out one level of the network topology (no AP). I do not have such an adapter at hand. However, I can get one.
connect the AP directly to the Linux server (cut out another component - bypass the switch). I mentioned this before, and this is something that I can do with relatively minor Linux configuration (the server has an unused Intel 1gigE NIC). When I get a moment, I’ll have a look.

-Chris

Fernando_Pereira · February 16, 2019, 4:55pm

Far from it, from personal experience. Roon engineers worked with me for quite a while trying to replicate this, including on my own LAN, with no success. Eventually changes on my LAN, either setting the central Ethernet switch to no IGMP snooping, or various system software/firmware changes that I do to maintain my network as a matter of course (new Ubiquiti router and wifi AP firmware, new Ubuntu version for Core server, new Android versions on new phones, …) made the problem disappear for good, so I dropped out of the debugging effort. Roon has stated multiple times that they have never been able to replicate in their own networks with Linux-based servers and multiple Android endpoints. It’s frustrating, yes, but not neglected.

evand · February 16, 2019, 5:33pm

In my case logs were eventually taken and then never followed up. I got tired of asking and let it go.

Fernando_Pereira · February 16, 2019, 8:59pm

That’s because they were not able to replicate the problem in the lab even with much more than logs, including packet traces from my home LAN.

CRo · February 16, 2019, 9:43pm

The nice thing is, the problem is consistent. It is repeatable. Here on this LAN.
I can list all the equipment, it’s not much, and you can build a copy of this environment. However, since other folks evidently have these issues, it would not seem to be confined to the brand and model of specific switch and AP.

What are the things that everyone with Android - Roon issues has in common? I’m asking - do tell.
From what I understand the stack is:

Roon remote or endpoint on an Android device
Wifi connectivity (ofcourse, it must be - there is no practical alternative to connecting a mobile device to a LAN)
Roon core on a Linux Server

I don’t see IGMP Snooping or switch settings as a common issue, because for example, I don’t have IGMP snooping on.

I was considering ways of testing the constellation previously (use a USB LAN adapter on the Android, connect the AP directly to the Core server).

Here’s a third idea: I have an OpenSSH client on my Android phone, I use it to tunnel to my LAN when I am on the go so I can stream from the Squeezebox Server to the Squeezebox Client on the phone. That worked OK because you can tell SB to transcode to MP3 for exmaple, or just use FLAC, which isn’t all that much data. [YES - SB Server is disabled right now].

So, actually, there are three ways to connect an Android mobile device to a LAN

Wifi
USB LAN Adapter (speculative, I have never tried this)
Celluar, meaning a remote connection.

I would need to port-forward the Roon ports via the OpenSSH tunnel. That’s no problem. I expect RAAT will eat through my cellular data allocation though.

@noris - is any of this of interest for you guys? Is this worth pursuing, or should I test something else?

-Chris

Fernando_Pereira · February 16, 2019, 11:08pm

Weird thing is, it was totally consistent on my home network for months, with multiple different Android endpoints, until it evaporated totally overnight. I did update my Netgear managed switch firmware before turning off IGMP snooping, and the Linux Ubuntu stack and Android kept being updated too, so who knows? My hunch is that there’s some race condition in how Roon/Mono interacts with the TCP/IP stack on Linux-based devices (which includes Android) that requires just a particular set of network circumstances to trigger consistently.

Rugby · February 17, 2019, 8:33pm

It is interesting. I"m on the other side of things, fortunately. I’ve never had an issue connecting my Note 3. Nor any other of my Galaxy Notes (4, 7, 8) or S6s, S7s, S8s, etc.

I have run the core on Windows, Rock, and about 8 different Linux distros when the Linux version was released, and never had an issue with Android connections.

I think I still have the hard drive with Ubuntu and RoonCore setup. Maybe I’ll spin that up and see if it is still provides a stable connection to my Android phones after I update it to the latest version.

Maybe a comparison between a setup which fails daily and one which never fails would have some value.

CRo · February 17, 2019, 8:39pm

Hi Rugby,

oh yes, that’d be quite interesting.

My two Android devices (with consistently reproducible problems) are a Blackberry Priv and a Samsung Note 3 (SM-N9005 ie. international GSM version).

-Chris

noris · February 23, 2019, 3:26am

Hello @CRo,

Thank you for sharing your results so far and apologies for the delay in getting back to you here. I spoke to the dev team again regarding this issue and in the past we have narrowed it down to a setting on managed switches.

To confirm that this is actually the switch and not some other external variable here, would you by any chance have an umanaged switch you can put in place of the managed one, keeping all of the other connections the same and see if that helps resolves the issue?

I understand that you intend to use the managed switch at the end of this testing but this will be a great data point to have. If you don’t have an unmanaged switch, then we can try connecting the AP directly to the Linux server as you suggested but logistically, the best test here would be to have everything remain constant and just have the managed switch be replaced by an unmanaged one.

If you are able to perform these tests, please do let us know your results. I appreciate you looking into this issue and hope that can make some progress here that will benefit Roon users with similar issues in the future.

Thanks,
Noris

CRo · February 23, 2019, 9:50pm

Hello @Noris,

Yes, I can get an unmanaged Ethernet switch from a colleague next week, and will try as you suggest.

In the mean time, I have created a second infrastructure setup, and am testing the functionality of Roon core/bridge/remotes without changing any of the networking stack.

Setup #1			Setup #2
[CentOS 7 - Roon Core]		[Centos 7 [Win 10 Pro 1709 - Roon Core]]
(GigE)				(GigE)
[Cisco SG300 Switch]		[Cisco SG300 Switch]
(GigE)				(GigE)
[TPLink EAP 245 AP]		[TPLink EAP 245 AP]
(Wifi N)			(Wifi N)
[Android - Roon remote]		[Android - Roon remote]

What you see deliniated above are two setups that are identical, except for the following point:
In setup #1, Roon Core is running directly on CentOS 7.
In setup #2, Roon Core is running on a Windows 10 virtual machine (KVM) running on CentOS 7.

This is a nice comparison, because as far as networking goes, it is the identical, same setup used in both cases. Also the CentOS server is the same, there literally are no configuration differences whatsoever. The Android remotes are also the identical units.

The result:

As already exhaustively documented, in setup #1, the Android remotes are unable to connect to the Roon core about 12 hours after start of the core service. They cannot connect again, until the Roon core service is restarted.
In setup #2, the Android remotes function perfectly, and are able to connect to the Roon core anytime, even after the Android device has been turned off and turned back on more than a day after the start of the Roon core service.

Perhaps the implementation of multicast in the Linux Roon core has some issues?

-Chris

Fernando_Pereira · February 24, 2019, 5:34am

That’s always been my suspicion, actually. Some weird interaction between the Linux network stack, Roon’s use of multicast (maybe something involving Mono?), and some network switches.

CRo · March 8, 2019, 9:17am

Hello @Noris,

it took a while getting a non-smart gigabit switch.

I have switched out the Cisco SG300 switch with a Netgear GS108 (a classic, blue metal case, these days they go for $22).

The test setup is identical to Setup #1 (with a Cisco SG300 fully-managed switch, as documented above in this thread) except for the dumb switch.

Setup #3
[CentOS 7 - Roon Core]	
(GigE)
[Netgear GS108 Switch (non-managed)]
(GigE)
[TPLink EAP 245 AP]
(Wifi N)
[Android - Roon remote]

The results are the same as with Setup #1, namely:

The Android Roon clients are unable to connect to the core after a few hours.
Restarting the Roon core service allows the Android remotes to connect again for a few hours, until the fail to connect again.

-Chris

noris · March 8, 2019, 10:48pm

Hi @CRo,

Thanks for performing that test and confirming that, these results do seem very interesting!

Previously we have been able to narrow it down to IGMP snooping on managed switches/routers but maybe this is not actually the root cause and just something that mitigates the issue.

In all of your setups that you have provided, I do not see a router model/manufacturer listed. Can you let me know what you are using or have you made the CentOS itself the router?

It looks like we’ll need to narrow the setup down even further to get closer to the root cause, I have two follow up suggestions:

You mentioned that it would be possible to remove the TPLink AP out of the equation by using a USB -> Ethernet adapter for the Android device, if you are still willing to give this a try it would be interesting to see if bypassing the AP has any effect.
If you are using the CentOS to manage the routing, I am wondering if there is any change if you temporarily use a standard consumer-grade router instead. Would you perhaps have a regular router around the house and can verify this aspect?

I think we’re definitely making some progress here, I look forward to hearing your reply!

Thanks,
Noris

CRo · March 8, 2019, 11:13pm

Hi @Noris,

the router is pfsense 2.4.4-RELEASE-p2 (AMD64) running in a KVM VM running on the same CentOS 7.6 Server where the Linux Roon core runs (and currently also the Windows 10 VM with the -other- Roon core also on it.)

Since the entire LAN, Roon core, AP, Androids, remotes, and endpoints are in the same subnet, is the router important? Yes to contact your (Roon Labs) servers, but if we leave the internet connection out of it, what does the router do on the local network? It does DNS and DHCP, but it does not route.

In fact, the ARP table on the CentOS Server should prevent any packets destined between Roon core and the other Roon devices from ever being sent to the router.

For testing, I am trying to think of a way of not using pfsense and instead using a “commodity” appliance without completely destroying my LAN and internet connection in the process.

I have a half-modern fritz!box 7390 (Router / Switch / DSL Modem / Wireless AP / DLNA Server / DECT base-station / VOIP Client all-in-one consumer “internet appliance”) laying around, but I’m afraid you’ll tell me that that is too smart of a device!! I am only half kidding!!!

-Chris

CRo · March 8, 2019, 11:29pm

PS. Since I had opened my mouth and suggested trying an USB-ethernet device, fair enough then, I ordered a “Plugable USB 2.0 OTG Mico Typ-B 10/100 Ethernet Adapter” and hope that one of the Android devices in the house will work with it. We shall see.

CRo · March 10, 2019, 10:38am

Hello @noris,

On we go testing Roon core connectivity in fun ways whilst selectively removing/changing single components of the infrastructure.

In setup #4, ROCK is running in a virtual machine (KVM) running on CentOS 7.6.
The rest of the infrastructure is identical to Setup #1 and #2 (detailed previously in the thread).

Setup #4
[Centos 7 [ROCK])
(GigE)
[Cisco SG300 Switch]
(GigE)
[TPLink EAP 245 AP]
(Wifi N)
[Android - Roon remote]

The result:

In setup #4 (same as in Setup #2), the Android remotes function perfectly, and are able to connect to the Roon core anytime, even after the Android device has been turned off and on many hours after the start of ROCK.

-Chris