Thanks @noris. I agree, very glad to not be crashing. But today while running a group of zones I noticed that I’m getting (what I think are) new error messages about re-authenticating when a rediscovery event happens. I’ve received a few of these messages that say it’s re-auth’ing until the 30th but keeps but it still refreshes:
05/29 16:50:37 Trace: [broker/accounts] doing auth refresh, next=5/30/2023 12:49:32 AM
05/29 16:51:27 Trace: [broker/accounts] doing auth refresh, next=5/30/2023 12:50:39 AM
05/29 16:52:27 Trace: [broker/accounts] doing auth refresh, next=5/30/2023 12:51:27 AM
The result seems to be that my playlists are stopping every few songs; a track will change, Roon UI will show the track is starting, then it will immediately stop. I tried to grab a batch of logs that happened immediately after a new song was started them stopped and pasted a redacted version below, hopefully it’s helpful. I notice it happens when changing from a FLAC to a low quality MP3 but I can’t say for certain it’s always only during that type of file change.
05/29 16:32:39 Trace: [Loopback PCM] [raatclient] SENT [2924]{"request":"teardown"}
05/29 16:32:39 Trace: [Living Roon + Basement Roon + Music-Room-851N + vumeters-lo-1] [zoneplayer/raat] Endpoint Loopback PCM State Changed: Prepared => Idle
05/29 16:32:39 Debug: [raat/tcpaudiosource] disconnecting
05/29 16:32:39 Trace: [Cambridge Audio 851N @ 192.168.1.216:35399] [raatclient] GOT [499836] {"status":"Teardown"}
05/29 16:32:39 Info: sleep 28ms after flush
05/29 16:32:39 Trace: [Loopback PCM] [raatclient] GOT [2313] {"status":"Teardown"}
05/29 16:32:39 Trace: [push2] retrying connection in 0ms
05/29 16:32:39 Trace: [broker/accounts] network reachability changed. refreshing
05/29 16:32:39 Trace: [broker/accounts] [heartbeat] now=5/29/2023 11:32:39 PM nextauthrefresh=5/30/2023 12:31:34 AM nextmachineallocate=5/30/2023 1:20:36 AM
05/29 16:32:39 Trace: [broker/accounts] doing auth refresh, next=5/30/2023 12:31:34 AM
05/29 16:32:39 Trace: [broker/accounts] refreshing account info for email='red' userid=red
05/29 16:32:39 Trace: [fiveaccountserver] POST https://accounts5.roonlabs.com/accounts/3/login
05/29 16:32:39 Trace: [fiveaccountserver] BODY token=red
05/29 16:32:39 Trace: [push2] exception thrown. restarting connection (The operation was canceled.)
05/29 16:32:39 Warn: [multicastreceiver] couldn't bind to iface 127.0.0.1:5350, message: Invalid argument
05/29 16:32:39 Warn: [multicastreceiver] couldn't bind to iface 192.168.1.15:5350, message: Invalid argument
05/29 16:32:39 Debug: [tidal] network reachability changed. refreshing token
05/29 16:32:39 Trace: [mobile] [remoteconnectivity] Port Verification started due to: network reachability changed, port verification not in progress, starting a new attempt
05/29 16:32:39 Trace: [roonapi] network reachability changed. Kicking off discovery cycle
05/29 16:32:39 Trace: [raat] [sood] Refreshing device list
05/29 16:32:39 Trace: [raatserver] [sood] Refreshing device list
05/29 16:32:39 Debug: [easyhttp] [125465] GET to https://api.roonlabs.net/push-manager/1/connect returned after 370 ms, status code: 200, request body size: 0 B
05/29 16:32:39 Debug: [push2] push connector url received from push manager: ws://push-connector-v2-1.prd-roonlabs-1.prd.roonlabs.net/
05/29 16:32:39 Trace: [push2] connecting to push2 connector at ws://push-connector-v2-1.prd-roonlabs-1.prd.roonlabs.net/
05/29 16:32:39 Debug: [easyhttp] [125467] POST to https://api.roonlabs.net/accounts5/accounts/3/login returned after 390 ms, status code: 200, request body size: 42 B
05/29 16:32:39 Trace: [fiveaccountserver] GOT {"status":"Success","userid":"red","token":"red","expiration":30,"email":"red","groups":[]}
05/29 16:32:39 Debug: [easyhttp] [125470] GET to https://api.roonlabs.net/porttest/1/myip returned after 283 ms, status code: 200, request body size: 0 B
05/29 16:32:39 Trace: [roonapi] [apiclient 192.168.1.26:34302] CONTINUE Changed {"message":"Extension Repository loaded (v1.0.15)","is_error":false}
05/29 16:32:39 Debug: [easyhttp] [125466] POST to https://api.roonlabs.net/discovery/1/query returned after 522 ms, status code: 200, request body size: 74 B
05/29 16:32:39 Debug: [easyhttp] [125469] GET to https://api.roonlabs.net/internetradio/2/api/location?format=msgpack& returned after 455 ms, status code: 200, request body size: 0 B
05/29 16:32:39 Trace: [radio/library] got location US
05/29 16:32:40 Debug: [easyhttp] [125468] GET to https://api.roonlabs.net/oauthcb/2/tidal/refresh?token=red returned after 628 ms, status code: 200, request body size: 0 B
05/29 16:32:40 Info: [broker/locations] updating location Tidal:Name=TIDAL:Id=red
05/29 16:32:40 Trace: [push2] connected to push2 connector at ws://push-connector-v2-1.prd-roonlabs-1.prd.roonlabs.net/
05/29 16:32:40 Trace: [fiveaccountserver] GET https://accounts5.roonlabs.com/accounts/3/profileslist?token=red
05/29 16:32:40 Trace: [fiveaccountserver] GET https://accounts5.roonlabs.com/accounts/3/userinfo?token=red&machineid=red
05/29 16:32:40 Trace: [broker/accounts] updated token. New expiration is 6/28/2023 4:32:40 PM
05/29 16:32:40 Trace: [broker/accounts] Data updated. AccountStatus=LoggedIn MachineStatus=Licensed UserId=red
05/29 16:32:40 Trace: [bits] myinfo: {"pushid":"broker/red","roon_auth_token"red","os":"Linux 5.15.0-69-generic","platform":"linuxx64","machineversion":200001272,"branch":"production","appmodifier":"","appname":"RoonServer"}
05/29 16:32:40 Info: [mobile] GOT HTTP API /portverify/red
05/29 16:32:40 Trace: [mobile] Got PortVerify Request from_guid=red
05/29 16:32:40 Trace: [mobile] Returning guid for verification: red
05/29 16:32:40 Debug: [easyhttp] [125474] POST to https://api.roonlabs.net/roonmobile/1/cores/announce returned after 230 ms, status code: 200, request body size: 1 KB
05/29 16:32:40 Debug: [easyhttp] [125473] GET to https://api.tidal.com/v1/sessions/red?countryCode=US returned after 277 ms, status code: 200, request body size: 0 B
05/29 16:32:40 Trace: [tidal/http] GET https://api.tidal.com/v1/sessions/red?countryCode=US => Success
05/29 16:32:40 Trace: [tidal] transition loginstatus from LoginSucceeded to LoginSucceeded
05/29 16:32:40 Debug: [easyhttp] [125476] GET to https://api.roonlabs.net/accounts5/accounts/3/userinfo?token=red&machineid=red returned after 212 ms, status code: 200, request body size: 0 B
05/29 16:32:40 Trace: [fiveaccountserver] GOT {"user":{"tfa":{"enabled":false},"userid":"red","firstname":"red","lastname":"red","email":"red","joinmailinglist":true,"allowpushnotifications":true,"class":"Normal","groups":[],"dncs":[],"trialallowed":false},"status":"Success"}
05/29 16:32:40 Trace: [broker/accounts] Data updated. AccountStatus=LoggedIn MachineStatus=Licensed UserId=red
05/29 16:32:40 Debug: [easyhttp] [125475] GET to https://api.roonlabs.net/accounts5/accounts/3/profileslist?token=red returned after 222 ms, status code: 200, request body size: 0 B
05/29 16:32:40 Trace: [fiveaccountserver] GOT {"status":"Success","profiles":[{"id":"red","name":"red","birthdate":"19740000"}]}
05/29 16:32:40 Trace: [broker/accounts] Data updated. AccountStatus=LoggedIn MachineStatus=Licensed UserId=red
05/29 16:32:40 Debug: [easyhttp] [125472] POST to https://api.roonlabs.net/porttest/1/port/check returned after 625 ms, status code: 200, request body size: 743 B
05/29 16:32:40 Debug: [easyhttp] [125477] POST to https://api.roonlabs.net/bits/1/q/roon.base.,roon.internet_discovery.,roon.debug.,roon.broker.,roon.dsp.,roon.sood.?roon_auth_token=red returned after 392 ms, status code: 200, request body size: 255 B
05/29 16:32:40 Trace: [bits] updated bits, in 400ms
05/29 16:32:40 Debug: [easyhttp] [125478] POST to https://api.roonlabs.net/roonmobile/1/cores/announce returned after 177 ms, status code: 200, request body size: 1 KB
05/29 16:32:40 Info: [mobile] GOT HTTP API /hello
05/29 16:32:40 Trace: [mobile] Got Hello Request body={"coreId":"red"}
05/29 16:32:40 Info: [mobile] GOT HTTP API /hello
05/29 16:32:40 Trace: [mobile] Got Hello Request body={"coreId":"red"}
05/29 16:32:41 Trace: [remoting/brokerserver] network reachability changed. Kicking off discovery cycle
05/29 16:32:44 Debug: [easyhttp] [125479] POST to https://api.roonlabs.net/discovery/1/register returned after 375 ms, status code: 200, request body size: 1 KB
05/29 16:32:44 Trace: [inetdiscovery] registered 1 devices, 5 services