obituary 5 Posted October 26, 2021 Share Posted October 26, 2021 (edited) Plugin version: 6.1.3 Kodi Version: 19.2 I've been having problems with watching movies/tv shows and the resume progress seeming very random. For example, I could finish a 43 minute TV show and at the end of it the resume flag is set in Kodi and the current position is the 10 minute mark. Often times, videos won't be marked as watched at all. 2021-10-25 23:35:09.075 Info SessionManager: Playback start reported by app Kodi 6.1.3 playing Interview with the Vampire. Started at 310 ms 2021-10-25 23:35:09.150 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 335ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=Tru e&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=3100000&RunTimeTicks=73534765625&VolumeLevel=100&IsMute d=False&PlaySessionId=e81a59f0ca7e4fde9709caf7f4b2d4a5 2021-10-25 23:35:09.162 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 348ms. http://192.168.2.160:8096/emby/Sessions/Playing?CanSeek=True&Queueab leMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=3100000&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&P laySessionId=e81a59f0ca7e4fde9709caf7f4b2d4a5 2021-10-25 23:35:09.162 Info Trakt: Playback Started 2021-10-25 23:35:09.163 Info HttpClient: POST https://api.trakt.tv/scrobble/start 2021-10-25 23:35:09.837 Info HttpClient: POST https://api.trakt.tv/scrobble/start 2021-10-25 23:35:10.709 Info HttpClient: POST https://api.trakt.tv/scrobble/start 2021-10-25 23:35:10.836 Error Trakt: Exception handled sending status update *** Error Report *** Version: 4.6.4.0 Command line: /app/emby/EmbyServer.dll -programdata /config -ffdetect /app/emby/ffdetect -ffmpeg /app/emby/ffmpeg -ffprobe /app/emby/ffprobe -restart exitcode 3 Operating system: Linux version 4.15.0-161-generic (buildd@lcy01-amd64-012) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04)) #169-Ubuntu SMP Fri Oct 15 13:41:54 UTC 20 Framework: .NET Core 3.1.13 OS/Process: x64/x64 Runtime: app/emby/System.Private.CoreLib.dll Processor count: 8 Data path: /config Application path: /app/emby MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: Locked at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsyncInternal(HttpRequestOptions options, String httpMethod) at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsync(HttpRequestOptions options, String httpMethod) at Trakt.Api.TraktApi.PostToTrakt(String url, Object data, CancellationToken cancellationToken, TraktUser traktUser) at Trakt.Api.TraktApi.SendMovieStatusUpdateAsync(Movie movie, MediaStatus mediaStatus, TraktUser traktUser, Single progressPercent, CancellationTo ken cancellationToken) at Trakt.ServerMediator.KernelPlaybackStart(Object sender, PlaybackProgressEventArgs e) Source: Emby.Server.Implementations TargetSite: Void MoveNext() 2021-10-25 23:36:09.150 Info SessionManager: Session a740e6840a07cfed30af3f65d773fabc has gone idle while playing 2021-10-25 23:36:09.150 Info SessionManager: Playback stopped reported by app Kodi 6.1.3 playing Interview with the Vampire. Stopped at 59310 ms 2021-10-25 23:36:09.160 Info Trakt: Playback Stopped 2021-10-25 23:36:09.160 Info Trakt: Item Not fully played. Tell trakt.tv we are no longer watching but don't scrobble 2021-10-25 23:36:09.160 Info HttpClient: POST https://api.trakt.tv/scrobble/pause 2021-10-25 23:36:09.795 Info HttpClient: POST https://api.trakt.tv/scrobble/pause 2021-10-25 23:36:10.397 Info HttpClient: POST https://api.trakt.tv/scrobble/pause 2021-10-25 23:36:10.491 Error Trakt: Error sending scrobble *** Error Report *** Version: 4.6.4.0 Command line: /app/emby/EmbyServer.dll -programdata /config -ffdetect /app/emby/ffdetect -ffmpeg /app/emby/ffmpeg -ffprobe /app/emby/ffprobe -restart exitcode 3 Operating system: Linux version 4.15.0-161-generic (buildd@lcy01-amd64-012) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04)) #169-Ubuntu SMP Fri Oct 15 13:41:54 UTC 20 Framework: .NET Core 3.1.13 OS/Process: x64/x64 Runtime: app/emby/System.Private.CoreLib.dll Processor count: 8 Data path: /config Application path: /app/emby MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: TooManyRequests at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsyncInternal(HttpRequestOptions options, String httpMethod) at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsync(HttpRequestOptions options, String httpMethod) at Trakt.Api.TraktApi.PostToTrakt(String url, Object data, CancellationToken cancellationToken, TraktUser traktUser) at Trakt.Api.TraktApi.SendMovieStatusUpdateAsync(Movie movie, MediaStatus mediaStatus, TraktUser traktUser, Single progressPercent, CancellationTo ken cancellationToken) at Trakt.ServerMediator.KernelPlaybackStopped(Object sender, PlaybackStopEventArgs e) Source: Emby.Server.Implementations TargetSite: Void MoveNext() Logs from the Kodi install running on the shield. It ends very abruptly after playback begins: 2021-10-25 16:35:04.158 T:9650 INFO <general>: INFO: EMBY.hooks.player.Player: [ onPlayBackStarted ] 2021-10-25 16:35:04.158 T:9650 INFO <general>: INFO: EMBY.hooks.player.Player: [ onAVChange ] 2021-10-25 16:35:04.159 T:9650 INFO <general>: Skipped 2 duplicate messages.. 2021-10-25 16:35:04.159 T:9650 INFO <general>: INFO: EMBY.hooks.player.Player: [ onAVStarted ] 2021-10-25 16:35:04.294 T:9650 INFO <general>: INFO: EMBY.hooks.player.Player: [ Queue playing item ] 2021-10-25 16:35:04.296 T:9650 INFO <general>: INFO: EMBY.hooks.player.Player: [ onAVChange ] 2021-10-25 16:35:05.167 T:14959 INFO <general>: INFO: EMBY.hooks.monitor.Monitor: [ UserDataChanged ] [{'PlaybackPositionTicks': 0, 'PlayCount': 2, 'IsFavorite': False, 'LastPlayedDate': '2021-10-25T23:35:09.0000000+00:00', 'Played': True, 'ItemId': '806'}] 2021-10-25 16:35:05.167 T:14959 INFO <general>: INFO: EMBY.hooks.monitor.Monitor: [ UserDataChanged skip update/806 ] 2021-10-25 16:36:05.158 T:21102 INFO <general>: INFO: EMBY.hooks.monitor.Monitor: [ UserDataChanged ] [{'PlaybackPositionTicks': 0, 'PlayCount': 2, 'IsFavorite': False, 'LastPlayedDate': '2021-10-25T23:35:09.0000000+00:00', 'Played': True, 'ItemId': '806'}] 2021-10-25 16:36:05.162 T:21102 INFO <general>: INFO: EMBY.database.db_open: [2e5c6b3aa9184e44827bf41d71f53e94] 1 rows updated. I'm interpreting this as the websocket immediately dying after playback is started and then the server timing out the session after exactly 1 minute. It is a not an "Active Player" in Emby's dashboard. I cannot send a message via the websocket, so I'm assuming the websocket has gone dead. I can try shutting off Trakt integration if we think that is breaking things, but I have a buddy who doesn't use the Trakt plugin who is having similar issues (Kodi + Shield also). Will debug logging in Kodi help with the plugin logging? It honestly seems like maybe the local emby server crashed and is no longer running. Edited October 26, 2021 by obituary Including versions Link to comment Share on other sites More sharing options...
Luke 36887 Posted October 26, 2021 Share Posted October 26, 2021 Hi, your Trakt account might be locked. You may need to contract Trakt support about that. Link to comment Share on other sites More sharing options...
obituary 5 Posted October 26, 2021 Author Share Posted October 26, 2021 3 minutes ago, Luke said: Hi, your Trakt account might be locked. You may need to contract Trakt support about that. Thanks. For now I just uninstalled the plugin to make this problem more digest-able. Link to comment Share on other sites More sharing options...
obituary 5 Posted October 26, 2021 Author Share Posted October 26, 2021 Just re-tested without trakt. Noticed an interesting behavior: uted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:03:08.539 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:03:08.540 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:03:08.541 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 2ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:03:08.542 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 2ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:08.541 Info SessionManager: Session a740e6840a07cfed30af3f65d773fabc has gone idle while playing 2021-10-26 01:04:08.542 Info SessionManager: Playback stopped reported by app Kodi 6.1.3 playing Interview with the Vampire. Stopped at 3019386 ms 2021-10-26 01:04:28.926 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:28.927 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:28.931 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 5ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:28.933 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 6ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:32.214 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:32.220 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 6ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:32.232 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:32.238 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 6ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:05:32.243 Info SessionManager: Session a740e6840a07cfed30af3f65d773fabc has gone idle while playing 2021-10-26 01:05:32.243 Info SessionManager: Playback stopped reported by app Kodi 6.1.3 playing Interview with the Vampire. Stopped at 3082418 ms This is me "seeking" around the file. When I seek...progress updates are sent to Emby. When I let the video play naturally, 1 minute later I get a timeout because the client is not sending any progress updates. Re-seeking seems to restart the session until it goes dead again. Link to comment Share on other sites More sharing options...
quickmic 1308 Posted October 26, 2021 Share Posted October 26, 2021 Please update to 6.1.5, I fixed some resume issues by this version. Unfortunately, I assume it will not solve the websocket issue but let's see. If there is still a problem, I need a complete Kodi.log The snapshot you posted looks absolutely fine. Link to comment Share on other sites More sharing options...
Solution quickmic 1308 Posted October 26, 2021 Solution Share Posted October 26, 2021 5 hours ago, obituary said: Just re-tested without trakt. Noticed an interesting behavior: uted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:03:08.539 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:03:08.540 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:03:08.541 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 2ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:03:08.542 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 2ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=29603862304&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:08.541 Info SessionManager: Session a740e6840a07cfed30af3f65d773fabc has gone idle while playing 2021-10-26 01:04:08.542 Info SessionManager: Playback stopped reported by app Kodi 6.1.3 playing Interview with the Vampire. Stopped at 3019386 ms 2021-10-26 01:04:28.926 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:28.927 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:28.931 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 5ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:28.933 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 6ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30505971679&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:32.214 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:32.220 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 6ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:04:32.232 Info Server: http/1.1 POST http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8. UserAgent: Kodi/6.1.3 2021-10-26 01:04:32.238 Info Server: http/1.1 Response 204 to 192.168.1.10. Time: 6ms. http://192.168.2.160:8096/emby/Sessions/Playing/Progress?CanSeek=True&QueueableMediaTypes=Video%2CAudio&IsPaused=False&ItemId=806&Type=movie&MediaSourceId=&PositionTicks=30234182128&RunTimeTicks=73534765625&VolumeLevel=100&IsMuted=False&PlaySessionId=4af126ed2fec47419a60530b717eaac8 2021-10-26 01:05:32.243 Info SessionManager: Session a740e6840a07cfed30af3f65d773fabc has gone idle while playing 2021-10-26 01:05:32.243 Info SessionManager: Playback stopped reported by app Kodi 6.1.3 playing Interview with the Vampire. Stopped at 3082418 ms This is me "seeking" around the file. When I seek...progress updates are sent to Emby. When I let the video play naturally, 1 minute later I get a timeout because the client is not sending any progress updates. Re-seeking seems to restart the session until it goes dead again. Sounds like the position tracker (this is a background thread in next-gen plugin) is not running. It should send the position every 5 seconds to Emby server. Link to comment Share on other sites More sharing options...
obituary 5 Posted October 28, 2021 Author Share Posted October 28, 2021 On 10/26/2021 at 12:05 AM, quickmic said: Sounds like the position tracker (this is a background thread in next-gen plugin) is not running. It should send the position every 5 seconds to Emby server. I installed 6.1.6 build 56 and it seems like this is working again. It did seem like this position tracker just wasn't even running. Not sure how that's possible. 1 Link to comment Share on other sites More sharing options...
Recommended Posts
Create an account or sign in to comment
You need to be a member in order to leave a comment
Create an account
Sign up for a new account in our community. It's easy!
Register a new accountSign in
Already have an account? Sign in here.
Sign In Now