DVR failed to record

Live TV & DVR
,
1

Server Version#: 1.21.1.3830
Player Version#:
Tuner Make/Model: Hauppage WinTV-dualHD
Guide/Lineup name:
Using XMLTV?:
Channel number/Name: ABC

I re-set up my DVR and recordings after the EPG update. We don’t have many recordings set up, and a lot of shows are on a winter hiatus, it seems. First one to come back on was The Good Doctor. This records on Mondays at 10 PM on ABC.
The recording on Jan 11th worked great.
But we never got a recording for this past monday’s episode (Jan 18th).

I have it set to record 2 min ahead and 2 min past just in case it starts early or runs a bit late.

Jan 18, 2021 21:58:01.005 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Subscription: Resolved subscription to library item 'The Good Doctor' (33535)
Jan 18, 2021 21:58:01.008 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Starting operation for 'The Good Doctor - E7 - The Uncertainty Principle' on channel 6.1.

This looks like the EPG portion of it is fine - it knows it is a new episode, and it is supposed to record it.

i see a number of errors like this, and a quick forum search shows this popping up a lot, so this might be inconsequential.

Jan 18, 2021 21:58:01.038 [0x7f0383fff700] ERROR - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Unable to find title for item of type 5
...
Jan 18, 2021 21:58:03.306 [0x7f039a5e1700] ERROR - [Transcoder] [mpeg2video @ 0x1580900] Invalid frame dimensions 0x0.

a short while later, i see this:

Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] TranscodeSession: timed out waiting to find duration for live session
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] ERROR - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Failed to start session.
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Streaming Resource: Terminated session 0x7f0370166140:b96f6a38-c058-44ec-bf7a-961f66955ed3 with reason Recording failed. Please check your tuner or antenna.
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] ERROR - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Recorder: Unable to create transcode session or session failed to start.
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Killing job.
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Signalling job ID 17222 with 9
Jan 18, 2021 21:58:28.426 [0x7f03457fa700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Job was already killed, not killing again.
Jan 18, 2021 21:58:28.426 [0x7f03457fa700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Job was already killed, not killing again.
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] ERROR - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Recorder: Error 12 (There was a transcoder error) starting the record, shutting things down.
Jan 18, 2021 21:58:28.426 [0x7f03457fa700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Stopping transcode session b96f6a38-c058-44ec-bf7a-961f66955ed3
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] MediaRecorderVirtual: setting stop time to 2021-01-18 21:58:28
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Grabber: Operation for 'The Good Doctor - E7 - The Uncertainty Principle' on channel 6.1 completed with status error (There was a transcoder error)
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Activity: Ended activity a243d9a1-bf0e-4bed-9be6-41d8625a88e2.
Jan 18, 2021 21:58:28.426 [0x7f0383fff700] ERROR - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Starting media grab failed.
Jan 18, 2021 21:58:28.427 [0x7f03457fa700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Whacked session b96f6a38-c058-44ec-bf7a-961f66955ed3, 1 remaining.
Jan 18, 2021 21:58:28.427 [0x7f03995df700] DEBUG - HTTP requesting GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Jan 18, 2021 21:58:28.427 [0x7f038bfff700] DEBUG - [Grabber/07322586c2e91568455adf0ca48a03e6396a5314] Activity: updated activity c489fd72-fd32-44ad-a0f6-5c56fcd495ac - completed 50.0% - Refreshing Sub
Jan 18, 2021 21:58:28.428 [0x7f03b20c9700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 17222 is -9 (signal: Killed)
Jan 18, 2021 21:58:28.629 [0x7f03995df700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450

any ideas what this means or why it failed? would like to get this figured out so I can be sure I get it recorded for next monday.

i saved the PMS log file and can provide if needed.

2

well, i ended up upgrading my plex server to a slightly newer version (nothing in the release notes mentioned any fixes) and restarted as part of the upgrade process.
the next upcoming episode recorded just fine.

another recording (Big Sky) also seems to have gone fine as well.

will probably never know why this one didn’t record, but i think all is well now…

3

well, that was short lived.
Big Sky S01E07 did not record on Feb 02, and i’m just seeing it now.
Big Sky S01E08 also did not record on Feb 09 (last night).

what’s extra weird is that the server seems to be stuck thinking it is still recording:
image

can anyone give some advice how to investigate this?

edit: attaching my Plex Media Server Log files from the server. probably of some use…
PMS.20210210T1125.tar.gz (3.0 MB)

4

The logs do confirm what you are seeing in the status - that recording gets to 100%, but then it doesn’t proceed to the next step:

Feb 09, 2021 23:02:00.878 [0x7fb57ffff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] Activity: updated activity 0dea69e7-c79a-4209-ae0b-dba811b993b9 - completed 100.0% - Recording

Looking in my logs at a successful recording, after it hits 100% Plex should then immediately proceed with processing the file from the .grab location, but yours doesn’t. While I don’t see associated errors in your logs, there are thousands of http request/responses like this in your logs that don’t appear in mine:

Feb 09, 2021 23:02:03.878 [0x7fb5f77fe700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP requesting GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:03.883 [0x7fb5f77fe700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP 200 response from GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:06.883 [0x7fb5d7fff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP requesting GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:06.888 [0x7fb5d7fff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP 200 response from GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:09.889 [0x7fb5f77fe700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP requesting GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:09.893 [0x7fb5f77fe700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP 200 response from GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:12.894 [0x7fb5d7fff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP requesting GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450
Feb 09, 2021 23:02:12.899 [0x7fb5d7fff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] HTTP 200 response from GET http://127.0.0.1:32600/devices/compound_device080dvb%23v4l%23%2fsys%2fdevices%2fpci0000%3a00%2f0000%3a00%3a1a.0%2fusb1%2f1-1%2f1-1.3%2f1-1.3%3a1.0%3a0013972450

I have a network tuner, not usb, and the http 200 response is an “ok” response, but still - this looks odd. Port 32600 is what the Plex Tuner Service listens on (e.g. it manages communications with your TV tuner.) I’d suggest starting with looking at your Plex Tuner Service log files to see if there is anything out of order.

5

yea, i saw all of those requests. i assume it is the server getting a recording status from the tuner because the server thinks it is still recording something.

It also appeared that when this one (failed) recording was going on, that the server thought there were now TWO active recordings…

Feb 09, 2021 22:59:27.618 [0x7fb5d7fff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] Activity: updated activity 0dea69e7-c79a-4209-ae0b-dba811b993b9 - completed 96.0% - Recording
Feb 09, 2021 22:59:27.618 [0x7fb5f6ffd700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] Activity: updated activity 4d193ed4-4481-45b9-b116-e92dbc72eb89 - completed 48.0% - Refreshing Sub

Feb 09, 2021 23:02:00.878 [0x7fb57ffff700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] Activity: updated activity 0dea69e7-c79a-4209-ae0b-dba811b993b9 - completed 100.0% - Recording
Feb 09, 2021 23:02:00.878 [0x7fb5f6ffd700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] Activity: updated activity 4d193ed4-4481-45b9-b116-e92dbc72eb89 - completed 50.0% - Refreshing Sub

looking through the logs for ‘4d193ed4-4481-45b9-b116-e92dbc72eb89’ shows this going on as far back in the logs as i can go:
Plex Media Server.5.log:Feb 08, 2021 18:14:24.848 [0x7fb5d5ffb700] DEBUG - Activity: updated activity 4d193ed4-4481-45b9-b116-e92dbc72eb89 - completed 0.0% - Refreshing Sub
it then changes to this when the recording actually starts:

Plex Media Server.2.log:Feb 09, 2021 21:58:39.449 [0x7fb606371700] DEBUG - [Grabber/585a6405e9a8a672e453c7bf1de1218295f1bacd] Activity: updated activity 4d193ed4-4481-45b9-b116-e92dbc72eb89 - completed 0.
5% - Refreshing Sub

and that repeats until it gets up to 50.0% and just… stops updating. not really sure what this activity is supposed to represent, but it seems to have been going on for a while, maybe its related to the failed recording from one week prior?

the line about 50% repeats until Feb 12, 13:29:16.592 when it seems to just suddenly stop. This is about the time when someone watches a movie from an unrelated library.
But the HTTP GET/200 response lines continue to repeat even now.

all in all, i have no idea what any of that means. haha

6

Have you looked at the Plex Tuner Service logs for the same time period, or would you upload them here? If you used the Plex web interface to extract logs, then they should be in the same zip file that you found the Plex Server logs.

7

Would really like it if Plex would attempt to restart the recording and stitch the .ts files back together? Maybe the recording dropped during a commercial and maybe I’d like to watch most of my episode… sheesh

8

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.