Client disconnects after loading album [Resolved - Build 223]

Oliver_Koch · March 23, 2017, 1:23pm

Hi,
I’ve a strange problem here with some albums not loading. The client disconnects or hangs…
Haven’t had the problem with version prior 1.3. Server is Linux Ubuntu, Client is Max OS X and Windows 10.

Log file says :

03/23 14:18:50 Info: [library/albumdetails] 79004d5730303031383037373737, 79004d5230303032393439333831
03/23 14:18:51 Info: [brokerserver] Client disconnected: 192.168.1.1:63226
03/23 14:18:51 Debug: [remoting] firing request callback with null because of dispose
03/23 14:18:51 Warn: posting to shutdown SynchronizationContextThread
03/23 14:18:51 Info: [brokerserver] Client connected: 192.168.1.1:63316
03/23 14:18:51 Trace: [SOOD] Adding User IP 192.168.1.1
03/23 14:18:51 Trace: [raat] [sood] Refreshing device list
03/23 14:18:51 Trace: [raatserver] [sood] Refreshing device list
03/23 14:18:51 Trace: SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=121829e7-d8f6-41ab-97c3-952b1292646b BrokerName='plex' }
03/23 14:18:51 Trace: SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=100300209 DisplayValue='1.3 (build 209) stable' Branch='stable' } }
 
03/23 14:22:30 Info: [library/albumdetails] Created details screen for LibraryAlbum[3600431, Nils Landgren - Eternal Beauty]
03/23 14:22:30 Info: [library/albumdetails] 79004d5730303032363134363636, 3e010a9de39b597619449960c5289bb5cf7b, 3e018184552561095942a6df04cdb4a62763, a6003235343636313831, 79004d5230303034313434333438
03/23 14:22:30 Trace: [music/query] performing album query
03/23 14:22:30 Trace: [music/query] query returned 3 Sooloos.Broker.Api.AlbumLite(s)
03/23 14:22:30 Trace: [music/query] performing album query
03/23 14:22:30 Trace: [music/query] query returned 0 Sooloos.Broker.Api.AlbumLite(s)
03/23 14:22:30 Debug: GET /image/jcyaaaaa.jpg
03/23 14:22:30 Debug: GET /image/fshaaaaa.256.jpg
03/23 14:22:34 Info: [library/albumdetails] Created details screen for LibraryAlbum[3590191, Richard Bonynge - Cilea: Adriana Lecouvreur]
03/23 14:22:34 Info: [library/albumdetails] 79004d5730303031333932303039, a60034343837343736
03/23 14:22:34 Info: [brokerserver] Client disconnected: 192.168.1.1:63316
03/23 14:22:34 Debug: [remoting] firing request callback with null because of dispose
03/23 14:22:34 Warn: posting to shutdown SynchronizationContextThread
03/23 14:22:35 Info: [brokerserver] Client connected: 192.168.1.1:63352
03/23 14:22:35 Trace: [SOOD] Adding User IP 192.168.1.1
03/23 14:22:35 Trace: [raat] [sood] Refreshing device list
03/23 14:22:35 Trace: [raatserver] [sood] Refreshing device list
03/23 14:22:35 Trace: SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=121829e7-d8f6-41ab-97c3-952b1292646b BrokerName='plex' }
03/23 14:22:35 Trace: SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=100300209 DisplayValue='1.3 (build 209) stable' Branch='stable' } }
03/23 14:22:37 Info: [stats] 2896mb Virtual, 668mb Physical, 319mb Managed, 0 Handles, 41 Threads

eric · March 23, 2017, 4:35pm

Hi @Oliver_Koch ---- Thank you for the report and my apologies for the troubles here. You are noticing this issue with both devices, OSX and Windows, correct? Can you please provide me with the specs of both?

Furthermore, have you tried reinstalling the remote application on the devices mentioned in your report? If so was the experience any different or was it the same?

-Eric

Oliver_Koch · March 23, 2017, 8:01pm

Problem appears on Mac, Windows and also tested on Android. Same behaviour on each device.
Mac is a Macbook Pro 2012, Mac OS Sierra 10.12.4 2.6 GHZ Intel Core i7, 8 GB Memory
Win Laptop is a Lenovo X1, 8 GB, i7, Windows 10 Version 1607. Roon client freshly installed.
Android Tablet is a Xperia Tablet Z, Android 5.1.
Standard language is english.
A client reinstall doesn’t change the behaviour.
It always appears on the same albums, all of them are classical with many titles and multiple disks. After the problem appears the client is unresponsive, a restart is necessary. Sometimes you get Loading album … infinitely, Sometimes kind a restart of the gui happens.
See below the roon log file from the Mac. I have clicked on the particular album at 20:53:46.

3/23 20:53:46 Warn: Error in web request https://push.roonlabs.com/push/1/connect: NetworkError (The remote server returned an error: (502) Bad Gateway.)
03/23 20:53:46 Trace: [push] request to manager failed
03/23 20:53:46 Trace: [push] retrying connection in 94691ms
03/23 20:53:50 Info: [stats] 3167mb Virtual, 502mb Physical, 75mb Managed, 40 Threads, FDs
03/23 20:53:51 Debug: UI-FWD: mode: albumdetails
03/23 20:53:51 Debug: GMS: saving nav stack
03/23 20:53:51 Debug: GMS: done saving nav stack
03/23 20:53:51 Debug: UI-NAV: album details / album: [object Sooloos_Broker_Api_AlbumLite_Proxy] / bookmarkdata:
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 33
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 21
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 27
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 33
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=7207
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 32
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=5060992
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 44
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 47
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 16
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 0
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 15
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 22
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 0
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 15
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 22
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 33
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 33
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 0
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 26
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 32
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 0
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=28
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 46
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 17
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 16
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 32
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=14266
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 52
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 34
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=1812861
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 28
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=50
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 27
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 47
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 32
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 45
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 47
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=62
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 0
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 15
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 22
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 33
03/23 20:53:51 Warn: [remoting] got response that doesn’t match up with a request rid=51
03/23 20:53:51 Warn: [remotingclient] unrecognized client cmd 52
03/23 20:53:51 Warn: [remoting] missing event: ‘’
03/23 20:53:51 Warn: [remoting] protocol violation: System.Collections.Generic.KeyNotFoundException: The given key was not present in the dictionary.
at System.Collections.Generic.Dictionary2[TKey,TValue].get_Item (System.Collections.Generic.TKey key) <0x111b62c00 + 0x00069> in <filename unknown>:0 at Sooloos.Broker.Remoting.TypeMappingHelper.GetUnknownTypeName (Int32 remotetypeid) <0x129619970 + 0x0002b> in <filename unknown>:0 at Sooloos.Broker.Remoting.RemotingClient.OnUpdateObj (System.Byte[] body) <0x12957fb60 + 0x000d2> in <filename unknown>:0 at Sooloos.Broker.Remoting.RemotingClient+<OnRequestReceived>c__AnonStorey0.<>m__3 () <0x12957f9c0 + 0x0001f> in <filename unknown>:0 at Sooloos.Broker.Remoting.RemotingClient._Flush (Nullable1 rid, System.Action[] actions) <0x11e409930 + 0x00063> in :0
at Sooloos.Broker.Remoting.RemotingClient+c__AnonStorey1.<>m__0 () <0x11e409870 + 0x0004b> in :0
03/23 20:53:51 Info: [brokerclient] Connection dropped: plex (121829e7-d8f6-41ab-97c3-952b1292646b) @ 192.168.1.2:9101
03/23 20:53:51 Debug: [remoting] firing request callback with null because of dispose
03/23 20:53:51 Debug: [remoting] firing request callback with null because of dispose
03/23 20:53:51 Debug: [remoting] firing request callback with null because of dispose
03/23 20:53:51 Warn: broker returned NetworkError trying to get persistent album id for 3683375
03/23 20:53:52 Info: [brokerclient] connecting to plex (121829e7-d8f6-41ab-97c3-952b1292646b) @ 192.168.1.2:9101 (attempt 1/6)
03/23 20:53:52 Info: SuspendZones
03/23 20:53:52 Info: [client/root] Broker changed plex (Remote Broker 121829e7-d8f6-41ab-97c3-952b1292646b) => null
03/23 20:53:52 Info: [client/root] Client is acting as a remote
03/23 20:53:52 Trace: [zone] [System Output] Suspend
03/23 20:53:52 Trace: [zone] [System Output] Stop
03/23 20:53:52 Info: [client/root] Broker ready changed True => False
03/23 20:53:52 Debug: trigger: appinitwasrun
03/23 20:53:52 Debug: trigger: no broker
03/23 20:53:52 Debug: [brokerclient] auth with plex (121829e7-d8f6-41ab-97c3-952b1292646b): Attempting to authenticate with no PIN
03/23 20:53:52 Trace: SENT REQUEST DistributedBroker.ConnectRequest={ ClientBrokerId=5e17f3db-4223-4b37-90f1-7b130d98423e ClientBrokerName=‘Olivers-MacBook-Pro’ ProtocolVersion=‘24’ ProtocolHash=‘18f5d0a5ad1f29bc6fdbd95666bb284a26f89f9c’ }
03/23 20:53:52 Trace: GOT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=121829e7-d8f6-41ab-97c3-952b1292646b BrokerName=‘plex’ }
03/23 20:53:52 Trace: GOT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status=‘UpToDate’ HasChangeLog=False CurrentVersion={ MachineValue=100300209 DisplayValue=‘1.3 (build 209) stable’ Branch=‘stable’ } }
03/23 20:53:52 Trace: [brokerclient] connected to plex (121829e7-d8f6-41ab-97c3-952b1292646b)
03/23 20:53:52 Info: SuspendZones
03/23 20:53:52 Trace: [zone] [System Output] Suspend
03/23 20:53:52 Trace: [zone] [System Output] Stop
03/23 20:53:52 Info: [client/root] Broker changed null => plex (Remote Broker 121829e7-d8f6-41ab-97c3-952b1292646b)
03/23 20:53:52 Info: [client/root] Client is acting as a remote
03/23 20:53:52 Info: [client/root] Broker ready changed False => True
03/23 20:53:52 Debug: trigger: appinitwasrun
03/23 20:53:52 Debug: trigger: apploaded, restoring nav stack
03/23 20:53:52 Debug: GMS: restoring nav stack
03/23 20:53:52 Debug: GMS: restoring nav stack data: trackbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: albumbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: artistbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: composerbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: workbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: tagbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: playlistbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: playlistdetails
03/23 20:53:52 Debug: GMS: restoring nav stack data: phonetrackbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: phonealbumbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: phoneartistbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: phonecomposerbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: phoneworkbrowser
03/23 20:53:52 Debug: GMS: restoring nav stack data: screens
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: home
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: home
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: home
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumdetails
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumdetails
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumdetails
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: home
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: genrebrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: genrebrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: genrebrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: genrebrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: home
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: search
03/23 20:53:52 Debug: UI-FWD: skipping fwd2 due to lazyload: albumdetails
03/23 20:53:52 Debug: GMS: found currentscreen in GMS file, going to index 19
03/23 20:53:52 Debug: UI-FORCE-UNLAZY: mode: albumdetails
03/23 20:53:52 Debug: GMS: trying to save nav stack, but nav stack stuff was in progress
03/23 20:53:52 Debug: UI-NAV: album details / album: / bookmarkdata: [object Broo.Runtime.BrooMap]
03/23 20:53:52 Debug: GMS: done restoring nav stack
03/23 20:54:02 Warn: Error in web request https://push.roonlabs.com/push/1/connect: NetworkError (The remote server returned an error: (502) Bad Gateway.)
03/23 20:54:02 Trace: [push] request to manager failed
03/23 20:54:02 Trace: [push] retrying connection in 122559ms
03/23 20:54:04 Trace: [appupdater] initial check for updates
03/23 20:54:04 Debug: [base/updater] Checking for updates: http://updates.roonlabs.com/update/?v=2&serial=BF076B1F-F70A-44B0-9669-9B7A35E9C68A&userid=f32bcac5-dcb0-4879-be50-56bb240075b2&platform=macosx&product=Roon&branding=roon&curbranch=stable&version=100300209&branch=stable
03/23 20:54:05 Debug: [appupdater] Update not needed
03/23 20:54:05 Info: [stats] 3170mb Virtual, 510mb Physical, 82mb Managed, 36 Threads, FDs
03/23 20:54:06 Info: Flushing kart data to server

eric · March 24, 2017, 6:12pm

Hi @Oliver_Koch ----- Thank you for following up and taking the time to answer my questions. Both are appreciated!

I would like to see if I can reproduce the same behavior you’re experiencing in house. Would it be possible for you to provide me a copy of one of the albums in question via a dropbox download link in a PM?

-Eric

Oliver_Koch · March 29, 2017, 1:36pm

Done as requested

eric · March 29, 2017, 4:58pm

HI @Oliver_Koch ----- Thank you for the follow up! Confirming that I have received and successfully downloaded the content. Once I have completed my testing I will be sure to touch base with my thoughts/findings. Your patience is appreciated!

-Eric

JWC · April 5, 2017, 10:48pm

I experience a very similar issue (infinite loading, sometimes iPad app disconnects) with one of my multi-disc classical albums in particular (Bach: St. Matthew Passion, Herreweghe, 3CDs, 68 tracks, properly identified by Roon). Other multi-disc albums with even more tracks do not have the same issue (for example, 4 CD Well-tempered Clavier, 96 tracks), so the length alone is not a sufficient condition.

Core: Synology 1515+ upgraded to 6GB RAM
Remotes: 9.7 iPad Pro, 2011 15 inch MacBook Pro

I can try uploading relevant log entries tonight.

Oliver_Koch · April 8, 2017, 12:28pm

Hey Eric, have you already tried to import the album?
I recently found a few more albums. They are all multiple disks (2) and classical or opera.

eric · April 10, 2017, 1:54pm

Hi @Oliver_Koch ----- Thank you for your patience and my apologies for the wait.

I did indeed have a chance to test with the media you have provided and I am seeing varying results across a few devices (OSX, Win10, Android, Ubuntu) Due to the fact that I am seeing this behavior intermittently, I have sent my report over to our QA department to see if this can be made 100% reproducible. Once my report has been updated and I have some feedback I will be sure to touch base again ASAP.

-Eric

JWC · April 27, 2017, 1:57am

Roon 1.3.223 seems to have solved this issue. Thanks for tracking this down!

eric · April 27, 2017, 4:04pm

@Oliver_Koch — Touching base to see how things are holding up after the last update(s). Has the experience been the same or improved?

Looking forward to your feedback!
-Eric

Oliver_Koch · April 28, 2017, 2:36pm

Hi Eric, yes seems to work now. I haven’t seen the issue with the known albums since the update.
THX

eric · April 30, 2017, 2:53pm

A post was split to a new topic: iPad and MacBook Pro Roon Remotes - Slow To Connect