Deep diving in the logs.
- Is this expected?
Sep 24, 2020 02:33:15.977 [0x7fcabbfff700] WARN - Denying access due to session lacking permission to transcode key /library/metadata/403
- When’s the last time analysis was run? According to the transcoder and the app, the duration and timing wasn’t right. It “ran off the end” unexpectedly but otherwise played to the end (6548.115 seconds of what was thought to be 6850.000 seconds).
Sep 24, 2020 04:21:27.161 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:41086 (WAN)] GET /:/timeline?audioStreamID=4737&bufferedTime=267053&duration=6850000&guid=com.plexapp.agents.themoviedb%3A%2F%2F22796%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F860&playbackTime=1570007&playQueueItemID=2486&ratingKey=860&state=playing&time=6548115&token=xxxxxxxxxxxxxxxxxxxx (9 live) TLS GZIP Signed-in Token (allie.ike)
Sep 24, 2020 04:21:27.161 [0x7fca70ff9700] DEBUG - Client [f9f709fb46499675-com-plexapp-android] reporting timeline state playing, progress of 6548115/6850000ms for guid=com.plexapp.agents.themoviedb://22796?lang=en, playbackTime=1570007ms ratingKey=860 url=, key=/library/metadata/860, containerKey=, metadataId=860, source=
Sep 24, 2020 04:21:27.161 [0x7fca70ff9700] DEBUG - [Now] User is allie.ike (ID: 40618858)
Sep 24, 2020 04:21:27.162 [0x7fca70ff9700] DEBUG - [Now] Device is Android (AFTT).
Sep 24, 2020 04:21:27.162 [0x7fca70ff9700] DEBUG - [Now] Profile is Android
Sep 24, 2020 04:21:27.162 [0x7fca70ff9700] DEBUG - [Now] Updated play state for /library/metadata/860.
Sep 24, 2020 04:21:27.162 [0x7fca70ff9700] DEBUG - Statistics: (f9f709fb46499675-com-plexapp-android) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 40618858
Sep 24, 2020 04:21:27.167 [0x7fcacffff700] DEBUG - Completed: [72.131.16.65:41086] 200 GET /:/timeline?audioStreamID=4737&bufferedTime=267053&duration=6850000&guid=com.plexapp.agents.themoviedb%3A%2F%2F22796%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F860&playbackTime=1570007&playQueueItemID=2486&ratingKey=860&state=playing&time=6548115&token=xxxxxxxxxxxxxxxxxxxx (9 live) TLS GZIP 6ms 801 bytes (pipelined: 159)
Sep 24, 2020 04:21:31.618 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:49299 (WAN)] GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00805.ts (9 live) TLS Signed-in
Sep 24, 2020 04:21:31.618 [0x7fca70ff9700] DEBUG - Asked for segment 805 from session.
Sep 24, 2020 04:21:31.618 [0x7fca70ff9700] DEBUG - Returning segment 805 from session
Sep 24, 2020 04:21:31.619 [0x7fca70ff9700] DEBUG - Content-Length of /mnt/magnesia_pool/plex_data/transcoding/Transcode/Sessions/plex-transcode-f9f709fb46499675-com-plexapp-android-1cc803d2-be9f-4293-babc-4526dada2ae4/media-00805.ts is 809180 (of total: 809180).
Sep 24, 2020 04:21:31.623 [0x7fcacffff700] DEBUG - Completed: [72.131.16.65:49299] 200 GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00805.ts (9 live) TLS 5ms 809180 bytes (pipelined: 2)
Sep 24, 2020 04:21:31.623 [0x7fcacffff700] DEBUG - Removed transcode data consumer, active count 1 => 0
Sep 24, 2020 04:21:35.890 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:49298 (WAN)] GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00806.ts (9 live) TLS Signed-in
Sep 24, 2020 04:21:35.890 [0x7fca70ff9700] DEBUG - Asked for segment 806 from session.
Sep 24, 2020 04:21:35.890 [0x7fca70ff9700] DEBUG - Returning segment 806 from session
Sep 24, 2020 04:21:35.891 [0x7fca70ff9700] DEBUG - Content-Length of /mnt/magnesia_pool/plex_data/transcoding/Transcode/Sessions/plex-transcode-f9f709fb46499675-com-plexapp-android-1cc803d2-be9f-4293-babc-4526dada2ae4/media-00806.ts is 622812 (of total: 622812).
Sep 24, 2020 04:21:35.894 [0x7fcacf7fe700] DEBUG - Completed: [72.131.16.65:49298] 200 GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00806.ts (9 live) TLS 3ms 622812 bytes (pipelined: 3)
Sep 24, 2020 04:21:35.894 [0x7fcacf7fe700] DEBUG - Removed transcode data consumer, active count 1 => 0
Sep 24, 2020 04:21:37.160 [0x7fcacffff700] DEBUG - Auth: authenticated user 40618858 as allie.ike
Sep 24, 2020 04:21:37.161 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:41086 (WAN)] GET /:/timeline?audioStreamID=4737&bufferedTime=276429&duration=6850000&guid=com.plexapp.agents.themoviedb%3A%2F%2F22796%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F860&playbackTime=1580011&playQueueItemID=2486&ratingKey=860&state=playing&time=6558135&token=xxxxxxxxxxxxxxxxxxxx (9 live) TLS GZIP Signed-in Token (allie.ike)
Sep 24, 2020 04:21:37.162 [0x7fca70ff9700] DEBUG - Client [f9f709fb46499675-com-plexapp-android] reporting timeline state playing, progress of 6558135/6850000ms for guid=com.plexapp.agents.themoviedb://22796?lang=en, playbackTime=1580011ms ratingKey=860 url=, key=/library/metadata/860, containerKey=, metadataId=860, source=
Sep 24, 2020 04:21:37.162 [0x7fca70ff9700] DEBUG - [Now] User is allie.ike (ID: 40618858)
Sep 24, 2020 04:21:37.162 [0x7fca70ff9700] DEBUG - [Now] Device is Android (AFTT).
Sep 24, 2020 04:21:37.162 [0x7fca70ff9700] DEBUG - [Now] Profile is Android
Sep 24, 2020 04:21:37.162 [0x7fca70ff9700] DEBUG - [Now] Updated play state for /library/metadata/860.
Sep 24, 2020 04:21:37.162 [0x7fca70ff9700] DEBUG - Statistics: (f9f709fb46499675-com-plexapp-android) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 40618858
Sep 24, 2020 04:21:37.165 [0x7fcacf7fe700] DEBUG - Completed: [72.131.16.65:41086] 200 GET /:/timeline?audioStreamID=4737&bufferedTime=276429&duration=6850000&guid=com.plexapp.agents.themoviedb%3A%2F%2F22796%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F860&playbackTime=1580011&playQueueItemID=2486&ratingKey=860&state=playing&time=6558135&token=xxxxxxxxxxxxxxxxxxxx (9 live) TLS GZIP 3ms 801 bytes (pipelined: 160)
Sep 24, 2020 04:21:39.556 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:49299 (WAN)] GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00807.ts (9 live) TLS Signed-in
Sep 24, 2020 04:21:39.556 [0x7fca70ff9700] DEBUG - Asked for segment 807 from session.
Sep 24, 2020 04:21:39.556 [0x7fca70ff9700] WARN - Transcode runner appears to have died.
Sep 24, 2020 04:21:39.656 [0x7fca70ff9700] DEBUG - Sending back blank segment for 807, we overestimated the number of segments.
Sep 24, 2020 04:21:39.656 [0x7fca70ff9700] DEBUG - Returning segment 807 from session
Sep 24, 2020 04:21:39.657 [0x7fca70ff9700] DEBUG - Content-Length of /usr/lib/plexmediaserver/Resources/empty is 0 (of total: 0).
Sep 24, 2020 04:21:39.657 [0x7fca70ff9700] DEBUG - Completed: [72.131.16.65:49299] 200 GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00807.ts (9 live) TLS 100ms 0 bytes (pipelined: 3)
Sep 24, 2020 04:21:43.266 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:49298 (WAN)] GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00808.ts (9 live) TLS Signed-in
Sep 24, 2020 04:21:43.266 [0x7fca70ff9700] DEBUG - Asked for segment 808 from session.
Sep 24, 2020 04:21:43.267 [0x7fca70ff9700] WARN - Transcode runner appears to have died.
Sep 24, 2020 04:21:43.367 [0x7fca70ff9700] DEBUG - Sending back blank segment for 808, we overestimated the number of segments.
Sep 24, 2020 04:21:43.367 [0x7fca70ff9700] DEBUG - Returning segment 808 from session
Sep 24, 2020 04:21:43.367 [0x7fca70ff9700] DEBUG - Content-Length of /usr/lib/plexmediaserver/Resources/empty is 0 (of total: 0).
Sep 24, 2020 04:21:43.367 [0x7fca70ff9700] DEBUG - Completed: [72.131.16.65:49298] 200 GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00808.ts (9 live) TLS 100ms 0 bytes (pipelined: 4)
Sep 24, 2020 04:21:43.390 [0x7fca70ff9700] DEBUG - Request: [72.131.16.65:49299 (WAN)] GET /video/:/transcode/universal/session/f9f709fb46499675-com-plexapp-android/base/00809.ts (9 live) TLS Signed-in
Sep 24, 2020 04:21:43.391 [0x7fca70ff9700] DEBUG - Asked for segment 809 from session.```
In short, that AFTT session played right up to the end, and seemed to seek forward and backward correctly on command (I watched all the block numbers increase and decrease)