Jump to content

[Issue] Watched/Unwatched/Position updates are breaking


obituary
 Share

Go to solution Solved by quickmic,

Recommended Posts

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 by obituary
Including versions
Link to comment
Share on other sites

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

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

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

  • Solution
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

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.

  • Like 1
Link to comment
Share on other sites

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 account

Sign in

Already have an account? Sign in here.

Sign In Now
 Share

×
×
  • Create New...