Plex DVR not recording

Plex Media Server Desktops & Laptops
,
61

@sa2000 said:

@captainnapalm said:
I’m having similar issues to the ones described in this thread. Episodes are recording to 100% but most are failing to move for some reason or another. For example, this is what I believe to be the relevant entries from my Plex Media Server logs while recording SNL last night. It aired from 9:29-11:02pm last night and Plex accurately saw the scheduled airtime and began recording, but it never finished, and I’m assuming this is the reason:

Feb 03, 2018 23:52:32.657 [0x14df665fe700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa'. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Trying airing at 2018-02-03 21:29:00 on channel 13.1. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Airing was in the past, ignoring. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Grabber: Operation for Saturday Night Live - E15 - Natalie Portman; Dua Lipa completed with status error (Cannot record airing in the past)

I left it alone overnight and when I checked on the status in the morning, the filesize of ts file was still continuing to grow (up to 8GB at that point) when I just decided to restart plex to clear it away.

Here’s the rest of the logs: https://hastebin.com/wosugerufu.sql

would need logs covering the time when the recording was to start

The download logs function is provided so we can get all the log files - there would be 6 and may be they would cover the earlier time

If the 6 logs are not sufficient - can look into editing the preferences to add a LogNumFiles entry
See https://support.plex.tv/articles/201105343-advanced-hidden-server-settings/

Also from log snippets one cannot confirm what version was in use

So please see if the logs zip goes back to before 11:02 pm - if you captured it
see https://support.plex.tv/articles/200250417-plex-media-server-log-files/

If not, we have to wait for next occurrence - perhaps with number of log files increased

If I’d paid attention to a few posts earlier, I would have noticed that. Luckily I do have the logs from shortly after recordings were to start.
drive.google.com/file/d/10A5cd_VXZoysCHu4jXnOtodgazgKeKI2/view?usp=sharing

62

@captainnapalm said:

@sa2000 said:

@captainnapalm said:
I’m having similar issues to the ones described in this thread. Episodes are recording to 100% but most are failing to move for some reason or another. For example, this is what I believe to be the relevant entries from my Plex Media Server logs while recording SNL last night. It aired from 9:29-11:02pm last night and Plex accurately saw the scheduled airtime and began recording, but it never finished, and I’m assuming this is the reason:

Feb 03, 2018 23:52:32.657 [0x14df665fe700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa'. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Trying airing at 2018-02-03 21:29:00 on channel 13.1. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Airing was in the past, ignoring. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Grabber: Operation for Saturday Night Live - E15 - Natalie Portman; Dua Lipa completed with status error (Cannot record airing in the past)

I left it alone overnight and when I checked on the status in the morning, the filesize of ts file was still continuing to grow (up to 8GB at that point) when I just decided to restart plex to clear it away.

Here’s the rest of the logs: https://hastebin.com/wosugerufu.sql

would need logs covering the time when the recording was to start

The download logs function is provided so we can get all the log files - there would be 6 and may be they would cover the earlier time

If the 6 logs are not sufficient - can look into editing the preferences to add a LogNumFiles entry
See https://support.plex.tv/articles/201105343-advanced-hidden-server-settings/

Also from log snippets one cannot confirm what version was in use

So please see if the logs zip goes back to before 11:02 pm - if you captured it
see https://support.plex.tv/articles/200250417-plex-media-server-log-files/

If not, we have to wait for next occurrence - perhaps with number of log files increased

If I’d paid attention to a few posts earlier, I would have noticed that. Luckily I do have the logs from shortly after recordings were to start.
drive.google.com/file/d/10A5cd_VXZoysCHu4jXnOtodgazgKeKI2/view?usp=sharing

The start of the recording looks good - no issues at this point in time. This is up to the time the logs were captured

Feb 03, 2018 21:29:00.906 [0x14df9cdfe700] DEBUG - DVR:Grabber: Saving recording to /tv/.grab/3d6598c273cd919ea7b3745ca97e13820b6eb30e
Feb 03, 2018 21:29:00.942 [0x14df9cdfe700] DEBUG - DVR:Grabber: Going to record for 5580 seconds, final URL is http://192.168.2.83:5004/auto/v13.1
Feb 03, 2018 21:29:00.943 [0x14df9cdfe700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' in 5580 seconds.
Feb 03, 2018 21:29:00.943 [0x14df9cdfe700] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.2.83:5004/auto/v13.1.
Feb 03, 2018 21:29:00.947 [0x14df9cdfe700] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Feb 03, 2018 21:29:00.947 [0x14df9cdfe700] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
. . . 
Feb 03, 2018 21:29:04.520 [0x14df9cdfe700] DEBUG - DVR:Recorder: It took 2.4 sec to start the session for http://192.168.2.83:5004/auto/v13.1
Feb 03, 2018 21:29:57.885 [0x14df9bbfd700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 1% - Recording
Feb 03, 2018 21:30:54.888 [0x14dfdcfff700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 2% - Recording
Feb 03, 2018 21:31:48.891 [0x14dfe45fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 3% - Recording
Feb 03, 2018 21:32:45.894 [0x14df9bbfd700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 4% - Recording
Feb 03, 2018 21:33:39.902 [0x14dfdd9fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 5% - Recording
Feb 03, 2018 21:34:36.909 [0x14dfb11fc700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 6% - Recording

What would be needed is logs from 23:00 to after 23:02 when the recording was going to stop and recording grab file saved

63

@sa2000 said:

@captainnapalm said:

@sa2000 said:

@captainnapalm said:
I’m having similar issues to the ones described in this thread. Episodes are recording to 100% but most are failing to move for some reason or another. For example, this is what I believe to be the relevant entries from my Plex Media Server logs while recording SNL last night. It aired from 9:29-11:02pm last night and Plex accurately saw the scheduled airtime and began recording, but it never finished, and I’m assuming this is the reason:

Feb 03, 2018 23:52:32.657 [0x14df665fe700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa'. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Trying airing at 2018-02-03 21:29:00 on channel 13.1. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Airing was in the past, ignoring. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Grabber: Operation for Saturday Night Live - E15 - Natalie Portman; Dua Lipa completed with status error (Cannot record airing in the past)

I left it alone overnight and when I checked on the status in the morning, the filesize of ts file was still continuing to grow (up to 8GB at that point) when I just decided to restart plex to clear it away.

Here’s the rest of the logs: https://hastebin.com/wosugerufu.sql

would need logs covering the time when the recording was to start

The download logs function is provided so we can get all the log files - there would be 6 and may be they would cover the earlier time

If the 6 logs are not sufficient - can look into editing the preferences to add a LogNumFiles entry
See https://support.plex.tv/articles/201105343-advanced-hidden-server-settings/

Also from log snippets one cannot confirm what version was in use

So please see if the logs zip goes back to before 11:02 pm - if you captured it
see https://support.plex.tv/articles/200250417-plex-media-server-log-files/

If not, we have to wait for next occurrence - perhaps with number of log files increased

If I’d paid attention to a few posts earlier, I would have noticed that. Luckily I do have the logs from shortly after recordings were to start.
drive.google.com/file/d/10A5cd_VXZoysCHu4jXnOtodgazgKeKI2/view?usp=sharing

The start of the recording looks good - no issues at this point in time. This is up to the time the logs were captured

Feb 03, 2018 21:29:00.906 [0x14df9cdfe700] DEBUG - DVR:Grabber: Saving recording to /tv/.grab/3d6598c273cd919ea7b3745ca97e13820b6eb30e
Feb 03, 2018 21:29:00.942 [0x14df9cdfe700] DEBUG - DVR:Grabber: Going to record for 5580 seconds, final URL is http://192.168.2.83:5004/auto/v13.1
Feb 03, 2018 21:29:00.943 [0x14df9cdfe700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' in 5580 seconds.
Feb 03, 2018 21:29:00.943 [0x14df9cdfe700] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.2.83:5004/auto/v13.1.
Feb 03, 2018 21:29:00.947 [0x14df9cdfe700] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Feb 03, 2018 21:29:00.947 [0x14df9cdfe700] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
. . . 
Feb 03, 2018 21:29:04.520 [0x14df9cdfe700] DEBUG - DVR:Recorder: It took 2.4 sec to start the session for http://192.168.2.83:5004/auto/v13.1
Feb 03, 2018 21:29:57.885 [0x14df9bbfd700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 1% - Recording
Feb 03, 2018 21:30:54.888 [0x14dfdcfff700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 2% - Recording
Feb 03, 2018 21:31:48.891 [0x14dfe45fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 3% - Recording
Feb 03, 2018 21:32:45.894 [0x14df9bbfd700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 4% - Recording
Feb 03, 2018 21:33:39.902 [0x14dfdd9fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 5% - Recording
Feb 03, 2018 21:34:36.909 [0x14dfb11fc700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 6% - Recording

What would be needed is logs from 23:00 to after 23:02 when the recording was going to stop and recording grab file saved

hopefully it’s in here:

drive.google.com/file/d/1V6vw9SWQIvFlnIktpptJHjGsXk75XL2L/view?usp=sharing

64

Same issue here, I see this in the logs “We seem to be missing the hash for media item”… the show is on Plex as recorded but there’s no recording anywhere, including the grab folder

65

DEBUG - DVR:Subscription: Failed to resolve subscription for ‘guid: com.gracenote.onconnect://show/378222 thumb: http://tmsimg.plex.tv/assets/p378222_b_v8_ac.jpg title: Enfoque type: show year: 2002’ to library item

I was also getting this error, and with more investigation I found it was failing to create the directory. My server runs of Ubuntu and I had spaces in my directory names. I’ve since correct spaces using “_”.

Some of you may want to try this out if you’re running under linux. Just a thought.

66

@captainnapalm said:

@sa2000 said:

@captainnapalm said:

@sa2000 said:

@captainnapalm said:
I’m having similar issues to the ones described in this thread. Episodes are recording to 100% but most are failing to move for some reason or another. For example, this is what I believe to be the relevant entries from my Plex Media Server logs while recording SNL last night. It aired from 9:29-11:02pm last night and Plex accurately saw the scheduled airtime and began recording, but it never finished, and I’m assuming this is the reason:

Feb 03, 2018 23:52:32.657 [0x14df665fe700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa'. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Trying airing at 2018-02-03 21:29:00 on channel 13.1. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Schedule: Airing was in the past, ignoring. Feb 03, 2018 23:52:32.663 [0x14df665fe700] DEBUG - DVR:Grabber: Operation for Saturday Night Live - E15 - Natalie Portman; Dua Lipa completed with status error (Cannot record airing in the past)

I left it alone overnight and when I checked on the status in the morning, the filesize of ts file was still continuing to grow (up to 8GB at that point) when I just decided to restart plex to clear it away.

Here’s the rest of the logs: https://hastebin.com/wosugerufu.sql

would need logs covering the time when the recording was to start

The download logs function is provided so we can get all the log files - there would be 6 and may be they would cover the earlier time

If the 6 logs are not sufficient - can look into editing the preferences to add a LogNumFiles entry
See https://support.plex.tv/articles/201105343-advanced-hidden-server-settings/

Also from log snippets one cannot confirm what version was in use

So please see if the logs zip goes back to before 11:02 pm - if you captured it
see https://support.plex.tv/articles/200250417-plex-media-server-log-files/

If not, we have to wait for next occurrence - perhaps with number of log files increased

If I’d paid attention to a few posts earlier, I would have noticed that. Luckily I do have the logs from shortly after recordings were to start.
drive.google.com/file/d/10A5cd_VXZoysCHu4jXnOtodgazgKeKI2/view?usp=sharing

The start of the recording looks good - no issues at this point in time. This is up to the time the logs were captured

Feb 03, 2018 21:29:00.906 [0x14df9cdfe700] DEBUG - DVR:Grabber: Saving recording to /tv/.grab/3d6598c273cd919ea7b3745ca97e13820b6eb30e
Feb 03, 2018 21:29:00.942 [0x14df9cdfe700] DEBUG - DVR:Grabber: Going to record for 5580 seconds, final URL is http://192.168.2.83:5004/auto/v13.1
Feb 03, 2018 21:29:00.943 [0x14df9cdfe700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' in 5580 seconds.
Feb 03, 2018 21:29:00.943 [0x14df9cdfe700] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.2.83:5004/auto/v13.1.
Feb 03, 2018 21:29:00.947 [0x14df9cdfe700] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Feb 03, 2018 21:29:00.947 [0x14df9cdfe700] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
. . . 
Feb 03, 2018 21:29:04.520 [0x14df9cdfe700] DEBUG - DVR:Recorder: It took 2.4 sec to start the session for http://192.168.2.83:5004/auto/v13.1
Feb 03, 2018 21:29:57.885 [0x14df9bbfd700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 1% - Recording
Feb 03, 2018 21:30:54.888 [0x14dfdcfff700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 2% - Recording
Feb 03, 2018 21:31:48.891 [0x14dfe45fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 3% - Recording
Feb 03, 2018 21:32:45.894 [0x14df9bbfd700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 4% - Recording
Feb 03, 2018 21:33:39.902 [0x14dfdd9fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 5% - Recording
Feb 03, 2018 21:34:36.909 [0x14dfb11fc700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 6% - Recording

What would be needed is logs from 23:00 to after 23:02 when the recording was going to stop and recording grab file saved

hopefully it’s in here:

drive.google.com/file/d/1V6vw9SWQIvFlnIktpptJHjGsXk75XL2L/view?usp=sharing

Sorry I missed your post.
There does appear to be an issue with count going negative and failure to stop the recording when 100% reached

Feb 03, 2018 23:02:02.418 [0x14df665fe700] DEBUG - Activity: updated activity ca2cf3ed-7996-45ce-a6ae-4c950ccf6774 - completed 100% - Recording
. . . 
Feb 03, 2018 23:11:45.576 [0x14dfbd3ff700] DEBUG - DVR:Subscription: Scheduling subscriptions.
Feb 03, 2018 23:11:45.601 [0x14dfbd3ff700] DEBUG - DVR:Subscription: Initialized 1 schedulers.
Feb 03, 2018 23:11:45.601 [0x14dfbd3ff700] DEBUG - DVR:Schedule: Scheduled an active operation 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' on tuner 0 between 2018-02-03 21:29:00 and 2018-02-03 23:02:00 on channel 13.1
Feb 03, 2018 23:11:45.602 [0x14dfbd3ff700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' in -585 seconds.

There have been a number of DVR related fixes since version 1.10.1.4602-f54242b6b of Plex Media Server
Has version 1.11.3.4803 resolved the issue ?

With regards to the negative time count, a fix is being produced and will be released in a subsequent release.

67

The latest 1.11.3.4803 doesn’t resolve my DVR issues unfortunately. The show is marked as “recorded” but there’s no recording anywhere and nothing in the grab directory :confused:

68

@vbadtz said:
The latest 1.11.3.4803 doesn’t resolve my DVR issues unfortunately. The show is marked as “recorded” but there’s no recording anywhere and nothing in the grab directory :confused:

There will be a fix for the negative timer showing in the log

Feb 03, 2018 23:11:45.602 [0x14dfbd3ff700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' in -585 seconds.

I am not sure if this double entry in the schedule is a factor

Feb 03, 2018 21:24:49.852 [0x14dfdcfff700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa'.
Feb 03, 2018 21:24:49.852 [0x14dfdcfff700] DEBUG - DVR:Grabber: Scheduling 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' for timed grab at 2018-02-03 21:29:00 (in 251 seconds)

Feb 03, 2018 21:24:49.858 [0x14dfdcfff700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa'.
Feb 03, 2018 21:24:49.859 [0x14dfdcfff700] DEBUG - DVR:Grabber: Scheduling 'Saturday Night Live - E15 - Natalie Portman; Dua Lipa' for timed grab at 2018-02-03 21:29:00 (in 251 seconds)

Same program processed twice.

Does the problem arise with specific programs?

Would like to see more examples of the problem and logs for it
and please try with beta release 1.12.0.4829

69

I’m seeing the same issue, often when trying to record shows from ABC. Either failed to grab media or there are issues once recorded and it takes 5 or 6 hours go show up in the Recently Added.

Mar 12, 2018 09:11:52.660 [30692] DEBUG - Activity: Ended activity 4fc2044e-ed65-41fb-b774-2f51d6f6cb7f.
Mar 12, 2018 09:11:52.661 [30692] ERROR - DVR:Grabber: Starting media grab failed.
Mar 12, 2018 09:11:52.664 [3890] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Mar 12, 2018 09:11:52.664 [3890] DEBUG - Auth: authenticated user 1 as dzeff
Mar 12, 2018 09:11:52.664 [3890] VERBOSE - Auth: Came in with a super-token, authorization succeeded.
Mar 12, 2018 09:11:52.665 [1766] DEBUG - Thread: Running async task started by thread 3890.

70

@dzeff said:
I’m seeing the same issue, often when trying to record shows from ABC. Either failed to grab media or there are issues once recorded and it takes 5 or 6 hours go show up in the Recently Added.

Mar 12, 2018 09:11:52.660 [30692] DEBUG - Activity: Ended activity 4fc2044e-ed65-41fb-b774-2f51d6f6cb7f.
Mar 12, 2018 09:11:52.661 [30692] ERROR - DVR:Grabber: Starting media grab failed.
Mar 12, 2018 09:11:52.664 [3890] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Mar 12, 2018 09:11:52.664 [3890] DEBUG - Auth: authenticated user 1 as dzeff
Mar 12, 2018 09:11:52.664 [3890] VERBOSE - Auth: Came in with a super-token, authorization succeeded.
Mar 12, 2018 09:11:52.665 [1766] DEBUG - Thread: Running async task started by thread 3890.

would need to have a view of what was going on. Could you attach the full logs zip collected after the failure
See https://support.plex.tv/articles/200250417-plex-media-server-log-files/

71

Sorry about the earlier Verbose logging. I turned that off and let it run for another 15-20 minutes. So look at the end of the log file. I can have more tomorrow without any verbose.

By far the vast majority of failed and troubled, recordings come from my local ABC channel.

72

I’ve attached another log, a few hours later. From the Programming guide, I selected to record a local news show that had about 50 minutes left and before I got to the Recording Schedule it had already failed. This appears to be the point of failure.

Mar 12, 2018 16:22:24.410 [12877] DEBUG - Thread: Running async task started by thread 3889.
Mar 12, 2018 16:22:24.410 [12877] DEBUG - Request: [192.168.1.9:51527 (Subnet)] POST /media/subscriptions?prefs%5BminVideoQuality%5D=0&prefs%5BreplaceLowerQuality%5D=false&prefs%5BrecordPartials%5D=true&prefs%5BstartOffsetMinutes%5D=0&prefs%5BendOffsetMinutes%5D=0&prefs%5BlineupChannel%5D=&prefs%5BstartTimeslot%5D=-1&prefs%5BcomskipEnabled%5D=-1&prefs%5BoneShot%5D=true&targetLibrarySectionID=6&targetSectionLocationID=&includeGrabs=1&hints[grandparentGuid]=com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F9142439&hints[grandparentThumb]=http%3A%2F%2Ftmsimg%2Eplex%2Etv%2Fassets%2Fp9142439_st_v8_aa%2Ejpg&hints[grandparentTitle]=KOMO%204%20News%204%3A00pm&hints[grandparentYear]=2012&hints[guid]=com%2Egracenote%2Eonconnect%3A%2F%2Fepisode%2F9142439%2F2018-03-12&hints[originallyAvailableAt]=2018-03-12&hints[parentIndex]=2018&hints[title]=&hints[type]=4&hints[year]=2018&params[airingChannels]=4%25252E1%253D4%25252E1%252520KOMODT%252520(ABC)&params[airingTimes]=1440&params[libraryType]=4&params[mediaProviderID]=3&type=4 (22 live) TLS GZIP Signed-in Token (dzeff)**
Mar 12, 2018 16:22:24.424 [12877] DEBUG - DVR:Subscription: Failed to resolve subscription for episode ‘grandparentGuid: com.gracenote.onconnect://show/9142439 grandparentThumb: http://tmsimg.plex.tv/assets/p9142439_st_v8_aa.jpg grandparentTitle: KOMO 4 News 4:00pm grandparentYear: 2012 guid: com.gracenote.onconnect://episode/9142439/2018-03-12 originallyAvailableAt: 2018-03-12 parentIndex: 2018 title: type: 4 year: 2018’ to library item**
Mar 12, 2018 16:22:24.483 [12877] DEBUG - DVR:Subscription: Failed to resolve subscription for episode ‘grandparentGuid: com.gracenote.onconnect://show/9142439 grandparentThumb: http://tmsimg.plex.tv/assets/p9142439_st_v8_aa.jpg grandparentTitle: KOMO 4 News 4:00pm grandparentYear: 2012 guid: com.gracenote.onconnect://episode/9142439/2018-03-12 originallyAvailableAt: 2018-03-12 parentIndex: 2018 title: type: 4 year: 2018’ to library item
Mar 12, 2018 16:22:24.484 [12877] DEBUG - DVR:Subscription: Checking in provider Program Guide
Mar 12, 2018 16:22:24.484 [12877] DEBUG - DVR:Subscription: MATCH for GUID scheme, directly checking.

73

A 3rd log file where I tried to just watch Live TV for that channel. Which I can get when I watch TV not through Plex but directly with the Coax in the TV.

74

I’m not sure that this is the right thread for this posting, because technically it IS recording however, nothing is in the DVR playlist, nor does it appear on my NVidia Shield’s file system.

If you are watching the playlist in Plex, I have ‘DVR’ setup, where the show should be stored you see a ‘cover’ appear and then disappears and it is not available to watch.

In the case of the attached log file, I was recording the TV show ‘Flipper’. I can see that it recorded, like I said, the cover appeared in the list of recorded shows but I do not have access to it anywhere.

Mar 13, 2018 05:30:00.042 [31799] DEBUG - Request: [127.0.0.1:53192 (Loopback)] POST /video/:/transcode/session/3be2d97e-6cdc-4f50-90b3-c563a047c13b/fbbb4682-4a09-4ab8-9054-4083f20e0dfe/seglist (16 live) Signed-in
Mar 13, 2018 05:30:00.045 [16121] DEBUG - Thread: Running async task started by thread 14672.
Mar 13, 2018 05:30:00.045 [16121] DEBUG - Request: [127.0.0.1:53193 (Loopback)] GET /livetv/sessions/3be2d97e-6cdc-4f50-90b3-c563a047c13b/690f60d4-6a16-4989-9390-40ab80706c1a/04099.ts (16 live) Signed-in
Mar 13, 2018 05:30:00.047 [31502] DEBUG - Thread: Running async task started by thread 14671.
Mar 13, 2018 05:30:00.047 [16816] DEBUG - Thread: Running async task started by thread 31725.
Mar 13, 2018 05:30:00.048 [31502] DEBUG - Request: [127.0.0.1:53194 (Loopback)] PUT /video/:/transcode/session/ca5fd1cb-0948-48c1-a327-6cbac3ee1ba0/154690e3-bb43-48b9-98f8-bafb4cefd207/progress?progress=-1.0&size=1218184352&remaining=-1&vdec_packets=77064&vdec_sw_ok=77062&speed=0.4&vdec_hw_status=0 (16 live) Signed-in Token (dzeff)
Mar 13, 2018 05:30:00.048 [16121] DEBUG - Content-Length of /storage/emulated/0/Android/data/com.plexapp.mediaserver.smb/cache/Transcode/Sessions/plex-transcode-3be2d97e-6cdc-4f50-90b3-c563a047c13b/media-04099.ts is 3119296.
Mar 13, 2018 05:30:00.049 [14672] DEBUG - Completed: [127.0.0.1:53194] 206 PUT /video/:/transcode/session/ca5fd1cb-0948-48c1-a327-6cbac3ee1ba0/154690e3-bb43-48b9-98f8-bafb4cefd207/progress?progress=-1.0&size=1218184352&remaining=-1&vdec_packets=77064&vdec_sw_ok=77062&speed=0.4&vdec_hw_status=0 (16 live) 1ms 326 bytes
Mar 13, 2018 05:30:00.111 [31799] DEBUG - Transcoder segment range: 0 - 7970
Mar 13, 2018 05:30:00.116 [14671] DEBUG - Completed after connection close: [127.0.0.1:53192] 200 POST /video/:/transcode/session/3be2d97e-6cdc-4f50-90b3-c563a047c13b/fbbb4682-4a09-4ab8-9054-4083f20e0dfe/seglist (16 live) 74ms 100 bytes
Mar 13, 2018 05:30:00.148 [31300] DEBUG - Thread: Running async task started by thread 14672.
Mar 13, 2018 05:30:00.148 [31300] DEBUG - Request: [127.0.0.1:53195 (Loopback)] GET /livetv/sessions/3be2d97e-6cdc-4f50-90b3-c563a047c13b/ca5fd1cb-0948-48c1-a327-6cbac3ee1ba0/05657.ts (16 live) Signed-in
Mar 13, 2018 05:30:00.150 [31300] DEBUG - Content-Length of /storage/emulated/0/Android/data/com.plexapp.mediaserver.smb/cache/Transcode/Sessions/plex-transcode-3be2d97e-6cdc-4f50-90b3-c563a047c13b/media-05657.ts is 1286108.
Mar 13, 2018 05:30:00.155 [32099] DEBUG - Thread: Running async task started by thread 14629.
Mar 13, 2018 05:30:00.191 [32099] DEBUG - DVR:Grabber: Starting operation for 'Flipper - E27 - Flipper's New Friends'.
Mar 13, 2018 05:30:00.206 [32099] DEBUG - Activity: registered new activity 8661610e-d522-4c9d-9519-0b75d2c4d407 - Recording
Mar 13, 2018 05:30:00.208 [2240] DEBUG - Thread: Running async task started by thread 32099.
Mar 13, 2018 05:30:00.208 [2240] DEBUG - Activity: updated activity 0a9b18e1-217e-4cba-bcb0-76c444897d6d - completed 100% - Recording
Mar 13, 2018 05:30:00.217 [14671] DEBUG - Completed: [127.0.0.1:53195] 200 GET /livetv/sessions/3be2d97e-6cdc-4f50-90b3-c563a047c13b/ca5fd1cb-0948-48c1-a327-6cbac3ee1ba0/05657.ts (16 live) 68ms 1286108 bytes
Mar 13, 2018 05:30:00.225 [32099] DEBUG - DVR:Grabber: Remote starting a media grab on device device://tv.plex.grabbers.tunerservice/dvb%23v4l%23%2fsys%2fdevices%2fplatform%2ftegra-xhci%2fusb2%2f2-2%2f2-2.1%3a0013984767 (Hauppauge WinTV-dualHD, supported) tuner 0.
Mar 13, 2018 05:30:00.248 [31725] DEBUG - Thread: Running async task started by thread 14671.
Mar 13, 2018 05:30:00.248 [31725] DEBUG - Request: [127.0.0.1:53196 (Loopback)] PUT /video/:/transcode/session/db237734-fa5d-4836-929b-bac744412937/cd001c23-9184-498b-88c4-4627b90c9be8/progress?progress=-1.0&size=445513188&remaining=-1&vdec_packets=52574&vdec_sw_ok=52573&speed=0.9&vdec_hw_status=0 (16 live) Signed-in Token (dzeff)
Mar 13, 2018 05:30:00.254 [14672] DEBUG - Completed: [127.0.0.1:53196] 206 PUT /video/:/transcode/session/db237734-fa5d-4836-929b-bac744412937/cd001c23-9184-498b-88c4-4627b90c9be8/progress?progress=-1.0&size=445513188&remaining=-1&vdec_packets=52574&vdec_sw_ok=52573&speed=0.9&vdec_hw_status=0 (16 live) 6ms 326 bytes
Mar 13, 2018 05:30:00.261 [32099] DEBUG - DVR:Subscription: Failed to resolve subscription for show 'guid: com.gracenote.onconnect://show/387352 thumb: https://image.tmdb.org/t/p/w154/oLNtjhHPf1ww3i3b3o1Wd9lhyic.jpg title: Flipper type: 2 year: 1964' to library item
Mar 13, 2018 05:30:00.275 [16835] DEBUG - Thread: Running async task started by thread 14672.
Mar 13, 2018 05:30:00.275 [16835] DEBUG - Request: [127.0.0.1:53197 (Loopback)] PUT /video/:/transcode/session/3be2d97e-6cdc-4f50-90b3-c563a047c13b/fbbb4682-4a09-4ab8-9054-4083f20e0dfe/progress?progress=-1.0&size=-22&remaining=-1&speed=1.3 (16 live) Signed-in Token (dzeff)
Mar 13, 2018 05:30:00.277 [14672] DEBUG - Completed: [127.0.0.1:53197] 206 PUT /video/:/transcode/session/3be2d97e-6cdc-4f50-90b3-c563a047c13b/fbbb4682-4a09-4ab8-9054-4083f20e0dfe/progress?progress=-1.0&size=-22&remaining=-1&speed=1.3 (16 live) 1ms 326 bytes
Mar 13, 2018 05:30:00.292 [32099] DEBUG - DVR:Grabber: Saving recording to "/sdcard/DVR/.grab/dd4209020dfde120ebda468407e71eb908368b5a"
Mar 13, 2018 05:30:00.310 [31846] DEBUG - Thread: Running async task started by thread 14629.
Mar 13, 2018 05:30:00.310 [31846] DEBUG - DVR:Grabber: Cancelling operation for 'Flipper - E26 - Cap'n Flint' with status complete.
Mar 13, 2018 05:30:00.310 [31846] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Mar 13, 2018 05:30:00.311 [31846] DEBUG - MediaRecorderVirtual: setting stop time to 1520944200
Mar 13, 2018 05:30:00.360 [32099] DEBUG - DVR:Grabber: Going to record for 1800 seconds, final URL is http://127.0.0.1:32600/devices/compound_device066dvb%23v4l%23%2fsys%2fdevices%2fplatform%2ftegra-xhci%2fusb2%2f2-2%2f2-2.1%3a0013984767/media/triplet%3A%2F%2F0%3A3149%3A4?param=%3C%3Fxml%20version%3D%221%2E0%22%20encoding%3D%22UTF-8%22%3F%3E%0A%3Ctunedata%3E%3Ctt%3E8%3C%2Ftt%3E%3Cdq%3E0%3C%2Fdq%3E%3Cdr%2F%3E%3Cfr%3E13%3C%2Ffr%3E%3Cmd%3E0%3C%2Fmd%3E%3Csr%3E0%3C%2Fsr%3E%3Cpl%3E0%3C%2Fpl%3E%3Clf%3E0%3C%2Flf%3E%3Cl1%3E0%3C%2Fl1%3E%3Cl2%3E0%3C%2Fl2%3E%3Cls%3E0%3C%2Fls%3E%3Cpp%3E0%3C%2Fpp%3E%3Chz%3E0%3C%2Fhz%3E%3Cin%3E0%3C%2Fin%3E%3Cfc%3E0%3C%2Ffc%3E%3Ct%3E3149%3C%2Ft%3E%3Cn%3E0%3C%2Fn%3E%3Cs%3E4%3C%2Fs%3E%3Cen%3E0%3C%2Fen%3E%3C%2Ftunedata%3E%0A
Mar 13, 2018 05:30:00.379 [31808] DEBUG - Thread: Running async task started by thread 14671.
Mar 13, 2018 05:30:00.379 [31808] DEBUG - Request: [127.0.0.1:53198 (Loopback)] PUT /video/:/transcode/session/c5498522-9eb6-4eaf-9152-4861e47e0709/c6882531-2477-4d93-9f7b-c4e7363ae6dc/progress?progress=-1.0&size=-22&remaining=-1&speed=1.2 (17 live) Signed-in Token (dzeff)
75

@sa2000, I just saw your earlier response for full logs. I’ve attached a 5 of the zip files that I have downloaded the last 2 days.

76

You have a Keep policy for Flipper set to keep episodes from the last 30 days. Plex uses the original air date when determining when episodes should be deleted, not date recorded. Since Flipper aired in 1964 all episodes are older than 30 days.

Mar 13, 2018 06:00:06.606 [32099] DEBUG - Garbage Collector: Deleting episode 27 - Flipper’s New Friends (beyond window of 30 days old)

77

Thanks Johnm_ColaSC, i might have at one time but have since removed that and just verified that is not in the current recording options. It sounds like the cache from previous information for that show has not been cleared?

There lingo seems UNintuitive in that IF I record the show now, having selected to keep episodes from last 30 days, I would expect that it would be kept for 30 days from recording and not from a shows original air date.

Is there a way to clear the Plex cache, clear things up and let it get new shows info, etc… without resetting everything and starting from scratch?

78

“unintuitive” is an understatement. while perhaps renaming the existing feature to “keep X days beyond first airing date” would help, actually deploying the feature as desired (keep for X days) would be far more useful.

79

From the Plex Setting Up Recordings Support Article:

Keep
Set the maximum number of unwatched episodes to keep for the show. Available options:

All episodes
5 episodes
3 episodes
1 episode
Episodes from the past 3 days
Episodes from the past 7 days
Episodes from the past 30 days
Examples:

If you choose “3 episodes” and you currently have 3 unwatched episodes, then when a new episode gets recorded, the oldest existing episode will automatically be removed.

“Episodes from the past X days” refers to when an episode first aired. So, if you record the nightly news and choose “Episodes from the past 7 days”, then after the 7th day, older unwatched episodes would start being removed. Conversely, if you have that setting chosen and you record a repeat airing of an episode that initially premiered a year ago, the episode would not be retained at all (since it was first aired more than 7 days ago).

@dzeff please make sure the library setting for the show is set to keep all episodes. The library show setting is what Garbage Collection uses when determining shows to keep, not the setting for the recording.

80

So as far as I can tell, and you can look at the screen captures - I have Flipper set to record all showings, and save all episodes - do not delete any. So why is there no Flipper when I go to look for it? I have created a library for all of my DVR recordings to go into and others go just fine, just not Flipper.

I have also attached the log file zip downloaded from my Plex Server.