Recording truncated due to invalid timestamp

[carlroth]

Server Version#: 1.24.2.4973 (via Plex pass docker image)
Player Version#: N/A
Tuner Make/Model: HDHomeRun PRIME
Guide/Lineup name: XFinity/Comcast
Using XMLTV?: N/A
Channel number/Name: Various

I’m seeing an issue with the Plex DVR feature where it randomly truncates recordings. From looking at the logs it appears that the live TV and/or transcoder process stops when it sees a timestamp in the stream that is out of range. Here is an example:

Sep 15, 2021 11:50:16.223 [0x7fac0408bb38] DEBUG - [Transcode] Transcoder segment range: 0 - 1214 (1214)
Sep 15, 2021 11:50:16.223 [0x7fac0408bb38] DEBUG - [Transcode] Transcoder segment range: 0 - 1215 (1214)
Sep 15, 2021 11:50:16.376 [0x7fac03f02b38] DEBUG - [Live/85d2f495-0a60-43f0-9984-f422feab43c1/cc22ab3f-3591-47d1-8e36-772ad44b297b] buildLiveM3U8: min 0 max 1214 ended 0
Sep 15, 2021 11:50:16.377 [0x7fac03f02b38] DEBUG - [Live/85d2f495-0a60-43f0-9984-f422feab43c1/cc22ab3f-3591-47d1-8e36-772ad44b297b] buildLiveM3U8: ended due to segment 18741.198911 past end time 2021-09-15 19:00:00.000000000 +0000
Sep 15, 2021 11:50:16.380 [0x7fac05541b38] DEBUG - Request: [127.0.0.1:60692 (Loopback)] GET /livetv/sessions/85d2f495-0a60-43f0-9984-f422feab43c1/cc22ab3f-3591-47d1-8e36-772ad44b297b/01213.ts (14 live) Signed-in
Sep 15, 2021 11:50:16.381 [0x7fac05541b38] DEBUG - Content-Length of /transcode/Transcode/Sessions/plex-transcode-85d2f495-0a60-43f0-9984-f422feab43c1/media-01213.ts is 556104 (of total: 556104).
Sep 15, 2021 11:50:16.389 [0x7fac0d251b38] DEBUG - Completed: [127.0.0.1:60692] 200 GET /livetv/sessions/85d2f495-0a60-43f0-9984-f422feab43c1/cc22ab3f-3591-47d1-8e36-772ad44b297b/01213.ts (14 live) 8ms 556104 bytes (pipelined: 2)
Sep 15, 2021 11:50:16.391 [0x7fac0d251b38] DEBUG - Removed transcode data consumer, active count 1 => 0
Sep 15, 2021 11:50:16.480 [0x7fac0ee58b38] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 15359 is 0 (success)
Sep 15, 2021 11:50:16.480 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Recording for 'The Pioneer Woman - E8 - Easy Entertaining' on channel 5fc76e1bfdb85d002d2da35e-5fc705e97dd72e002d6dd201 stopped with status complete.
Sep 15, 2021 11:50:16.480 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Using recording status.
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Recorder: No more consumers, stopping.
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Recorder: Asked to stop recording 'The Pioneer Woman - E8 - Easy Entertaining' on channel 5fc76e1bfdb85d002d2da35e-5fc705e97dd72e002d6dd201.
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Recorder: Stopping transcode session.
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Killing job.
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Signalling job ID 15335 with 9
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Job was already killed, not killing again.
Sep 15, 2021 11:50:16.480 [0x7fac056b9b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Stopping transcode session 85d2f495-0a60-43f0-9984-f422feab43c1
Sep 15, 2021 11:50:16.481 [0x7fac0411ab38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Cleaning directory for session 85d2f495-0a60-43f0-9984-f422feab43c1 (/transcode/Transcode/Sessions/plex-transcode-85d2f495-0a60-43f0-9984-f422feab43c1)
Sep 15, 2021 11:50:16.482 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Activity: updated activity bad981fa-7239-40ac-91db-3e00978711ca - completed 100.0% - Recording
Sep 15, 2021 11:50:16.482 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Activity: updated activity bad981fa-7239-40ac-91db-3e00978711ca - completed 100.0% - Recording
Sep 15, 2021 11:50:16.482 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] [MI] Opening input file: "/auto/tivo/series/.grab/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406-ec33d704f288dc07f8df582cf3ac1b0f0fd4904c/The Pioneer Woman (2011) - S18E08 - Easy Entertaining.ts"
Sep 15, 2021 11:50:16.482 [0x7fac049a1b38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] Activity: updated activity 3a90a983-bb31-4312-b6b6-00d7ad184356 - completed 34.3% - Refreshing Sub
Sep 15, 2021 11:50:16.483 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] [FFMPEG] - Opening '/auto/tivo/series/.grab/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406-ec33d704f288dc07f8df582cf3ac1b0f0fd4904c/The Pioneer Woman (2011) - S18E08 - Easy Entertaining.ts' for reading
Sep 15, 2021 11:50:16.483 [0x7fac04d5bb38] DEBUG - [Grabber/3f19d9b1aacabdfc504edad6937ed0bb2a1b9406] [FFMPEG] - Setting default whitelist 'file,crypto'
Sep 15, 2021 11:50:16.486 [0x7fac0ee58b38] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 15335 is -9 (signal: Killed)

In the above case, the episode being recorded was 30min/1800s; the segment timestamp it reported is well past the end of the recording and this tripped some sort of assertion.

These are difficult failures to identify, since

1. The failure messages only appear when debug logging is enabled
2. In order to correctly identify the failure, you need the logs from the start of the recording (when the recording duration from the EPG is reported) and the end of the recording
3. The Linux docker image provided by Plex aggressively rotates the logs, such that there is only an hour or so of debug messages on disk at any moment

This issue has been reported in the forums many times in the last year, see e.g.

Recording intermittently fails - ended due to segment past end time

OS Ubuntu 18.04, Plex version 1.18.7.2415 Recordings intermittently fail - example of the first indication in the logs in each case is: Feb 17, 2020 02:21:28 DEBUG - buildLiveM3U8: ended due to segment 10791.684789 past end time 2020-02-17 04:45:00.000000000 +0000 The end time is correct, but the conclusion that 4:45am is before 2:21am isn’t! The error occurs after random recording durations - 3 seconds, 15 mins, 21 mins… but sometimes also records correctly. I believe this has been happen…

Recording stopped 37 minutes into 2 hour sporting event

Server Version#: 1.20.2.3402 Player Version#: N/A Tuner Make/Model: HDHomerun Connect Duo Guide/Lineup name: Using XMLTV?: Don’t think so Channel number/Name: 49.1 Without any intervention from a person, the DVR service stopped recording a game 37 minutes into the match, well short of the 2hrs + 60 min extra scheduled for that recording. Here’s the server log at the time of interest: Oct 11, 2020 19:37:38.102 [0x7f6f467fc700] DEBUG - Request: [127.0.0.1:35118 (Loopback)] GET /livetv/sessi…

Recordings cancelled after 2 minutes, "Recorder: No more consumers, stopping."

Server Version#: 1.20.3.3483 Player Version#: [File wasn’t being played, but I normally play on a Roku or Shield] Tuner Make/Model: HDHomeRun Prime I can provide more details as needed, but I’m running into a problem that seems to have come up before. I’m recording from an HDHomeRun Prime to a local hard drive. I’ve recorded five movies over two days (Hello Hallmark Christmas season); three completed successfully, but the other two stopped after two minutes. The log entries look like this: O…

Plagued by Partial Recordings

It is better to upload the full logs generated from Server>Troubleshooting>Download logs. Looks like a weak signal causing a missing segment to be (not) generated. Could also be a space/storage issue if you are writing to the internal storage. Apr 09, 2020 17:31:47.071 [31252] DEBUG - DVR:Grabber: Signal information for tune on channel 7.1: strength: 42, quality: 67 Apr 09, 2020 17:31:47.083 [2997] DEBUG - buildLiveM3U8: min 0 max 104 ended 0 Apr 09, 2020 17:31:47.086 [4444] DEBUG - Request: …

In all cases there was no followup from Plex engineers, and thread/bug report was closed after 90 days of inactivity.

This appears to be a persistent issue with the DVR feature, can we please get some traction on this?

[pl_5309]

Increase the number of log files via LogNumFiles in your Preferences.xml file. (Advanced, Hidden Server Settings | Plex Support)

To get anywhere you need to upload the log bundle (debug but not verbose).

[carlroth]

OK here is another example with logs. Apologies in advance for my terrible taste in TV programs.

Plex tried to record
‘Dude You’re Screwed (2013) - S02E01 - Epic Fail’
on 2021-09-17 06:00 (60min/3600s duration)
the recording was truncated after 39min (2349s)

See

Sep 17, 2021 06:39:12.972 [0x7fac0376bb38] DEBUG - [Live/9f5bce4c-6cc7-41ae-8454-4ad51bf7fb33/34a3999e-dee2-46ec-abb8-d801b8470eb0] buildLiveM3U8: ended due to segment 19877.383222 past end time 2021-09-17 14:00:00.000000000 +0000
...
Sep 17, 2021 06:39:13.364 [0x7fac03b67b38] DEBUG - [Grabber/98b579d1e1e2af9893d68e37974f027caa05699d] [MI]  *  [mpegts h264/ac3] Duration: 2349723ms, 1280x720 (1.777778) 59.940fps, bitrate=4127kbps, audio channels=6, optimizedForStreaming=0 ("/auto/tivo/series/.grab/98b579d1e1e2af9893d68e37974f027caa05699d-ec33d704f288dc07f8df582cf3ac1b0f0fd4904c/Dude You're Screwed (2013) - S02E01 - Epic Fail.ts")

Plex Media Server Logs_2021-09-17_07-11-48.zip (7.5 MB)

[carlroth]

Here is another example. A recording of “The Accountant” (9000s) stopped after 3265s.logs.zip (12.7 MB)

Sep 22, 2021 18:24:27.784 [0x7f1025ee0b38] DEBUG - [Live/19352351-18ea-4f85-89dc-cbc06209b1fa/552cc76e-7174-48c3-8b12-af7111cc6cdd] buildLiveM3U8: min 0 max 3265 ended 0
Sep 22, 2021 18:24:27.788 [0x7f1025ee0b38] DEBUG - [Live/19352351-18ea-4f85-89dc-cbc06209b1fa/552cc76e-7174-48c3-8b12-af7111cc6cdd] buildLiveM3U8: ended due to segment 20793.426278 past end time 2021-09-23 03:00:00.000000000 +0000

[pl_5309]

From just before those lines:

p 22, 2021 18:24:28.341 [0x7f102575fb38] DEBUG - [Grabber/30b0d66b37c43505761768cb38a459f3dfa2a273] Recorder: Asked to stop recording 'The Accountant (2016)' on channel 5fc76e1bfdb85d002d2da35e-5fc705e98aba71002d8b7a50.
	Line 22614: Sep 22, 2021 18:24:28.342 [0x7f1026080b38] DEBUG - [Grabber/30b0d66b37c43505761768cb38a459f3dfa2a273] Recording for 'The Accountant (2016)' on channel 5fc76e1bfdb85d002d2da35e-5fc705e98aba71002d8b7a50 stopped with status complete.

Were you watching while recording or someone/another program grab the tuner?

[carlroth]

At 18:24:27.788 the transcoder shows a discontinuity error, and afterwards, at 18:24:28.342, the grabber logic interprets that as a “complete” status. I was not watching another program at the time, and ending timestamp for the transcode does not correspond to the start of another program (not on the hour or half-hour etc.)
Note that when this type of failure occurs, the recording is otherwise processed and staged to disk (thumbnail processing etc.) but the program info (XML) indicates that the recording is “complete” but “cancelled”. It drops off of the recording schedule and the DVR does not retry another recording.