Why is recording failing

General Discussions Plex Features
1

On a few occasions recently Plex/HDHomeRun seems to be recording a movie but when I look in the folder, and within Plex movies, nothing is showing. If I look at the recording schedule it implies that the film recording completed. The logs show that the recording started and was written to the .grab folder. The logs also show that the recording completed but I can’t see anything that says the file was copied from .grab folder to the correct destination folder - shares/public/Recorded TV Movies. PMS is 1.9.3 on a WD PR4100. Can anyone advise how to get my recordings working again?

Extract from logs:

Oct 19, 2017 01:52:48.746 [0x7f033b11f700] DEBUG - Versions: garbage collecting

#20131 Oct 19, 2017 01:52:48.750 [0x7f033b11f700] DEBUG - Versions: garbage collected in 0.0 seconds
#20132 Oct 19, 2017 01:55:00.613 [0x7f033dfff700] DEBUG - DVR:Grabber: Starting operation for ‘Letters to Juliet (2010)’.
#20133 Oct 19, 2017 01:55:00.615 [0x7f033dfff700] DEBUG - Activity: registered new activity e4eafa65-9a13-4fa8-9658-e1969dbf6210 - Recording
#20134 Oct 19, 2017 01:55:00.616 [0x7f033dfff700] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/123173A0 (Silicondust HDHomeRun CONNECT, supported) tuner 0.
#20135 Oct 19, 2017 01:55:00.625 [0x7f033dfff700] DEBUG - DVR:Subscription: Failed to resolve subscription for ‘guid: com.gracenote.tms://movie/MV003353650000 thumb: https://image.tmdb.org/t/p/w154/kUBSfYpsE1RLdl2WZL2YMJfNOEm.jpg title: Letters to Juliet type: 1 year: 2010’ to library item
#20136 Oct 19, 2017 01:55:00.626 [0x7f033dfff700] DEBUG - DVR:Grabber: Saving recording to /shares/Public/Recorded TV Movies/.grab/8796a10d55b128cad3b187c1727facd29caa944c
#20137 Oct 19, 2017 01:55:00.665 [0x7f033dfff700] DEBUG - HTTP requesting GET http://192.168.1.112:80/lineup.json
#20138 Oct 19, 2017 01:55:00.693 [0x7f033dfff700] DEBUG - HTTP 200 response from GET http://192.168.1.112:80/lineup.json
#20139 Oct 19, 2017 01:55:00.696 [0x7f033dfff700] DEBUG - DVR:Grabber: Going to record for 6600 seconds, final URL is http://192.168.1.112:5004/auto/v4
#20140 Oct 19, 2017 01:55:00.698 [0x7f033dfff700] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘Letters to Juliet (2010)’ in 6600 seconds.
#20141 Oct 19, 2017 01:55:01.735 [0x7f034a26b700] DEBUG - EPG[onconnect]: Next thing to start/end is at 2017-10-19 01:00:00 (in 300 seconds)
#20142 Oct 19, 2017 01:56:06.627 [0x7f034da23700] DEBUG - Activity: updated activity e4eafa65-9a13-4fa8-9658-e1969dbf6210 - completed 1% - Recording
#20143 Oct 19, 2017 01:56:48.732 [0x7f034a26b700] DEBUG - EPG[onconnect]: Purging 3 airings which completed in the past.

Followed by:
#27297 Oct 19, 2017 03:41:49.707 [0x7f0338b09700] DEBUG - EPG[onconnect]: Not purging media ID 1346 because it’s currently active.
#27298 Oct 19, 2017 03:41:49.707 [0x7f0338b09700] DEBUG - EPG[onconnect]: Not purging media ID 1217 because it’s currently active.
#27299 Oct 19, 2017 03:41:49.707 [0x7f0338b09700] DEBUG - EPG[onconnect]: Not purging media ID 834 because it’s currently active.
#27300 Oct 19, 2017 03:42:49.766 [0x7f034da23700] DEBUG - Activity: updated activity e4eafa65-9a13-4fa8-9658-e1969dbf6210 - completed 98% - Recording
#27301 Oct 19, 2017 03:43:55.778 [0x7f034da23700] DEBUG - Activity: updated activity e4eafa65-9a13-4fa8-9658-e1969dbf6210 - completed 99% - Recording
#27302 Oct 19, 2017 03:45:00.931 [0x7f034da23700] DEBUG - DVR:Grabber: Cancelling operation for ‘Letters to Juliet (2010)’ with status complete.
#27303 Oct 19, 2017 03:45:00.931 [0x7f034da23700] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
#27304 Oct 19, 2017 03:45:01.526 [0x7f0338b09700] DEBUG - EPG[onconnect]: Next thing to start/end is at 2017-10-19 02:50:00 (in 300 seconds)
#27305 Oct 19, 2017 03:45:01.790 [0x7f034a26b700] DEBUG - Activity: updated activity e4eafa65-9a13-4fa8-9658-e1969dbf6210 - completed 100% - Recording
#27306 Oct 19, 2017 03:46:49.729 [0x7f034a26b700] DEBUG - EPG[onconnect]: Purging 4 airings which completed in the past.
#27307 Oct 19, 2017 03:46:49.729 [0x7f034a26b700] DEBUG - EPG[onconnect]: Not purging media ID 1346 because it’s currently active.
#27308 Oct 19, 2017 03:46:49.729 [0x7f034a26b700] DEBUG - EPG[onconnect]: Not purging media ID 1217 because it’s currently active.
#27309 Oct 19, 2017 03:46:49.729 [0x7f034a26b700] DEBUG - EPG[onconnect]: Not purging media ID 834 because it’s currently active.

2

The full logs would be better to look at. Can you post the zip file of the logs?

3

Thanks. You should have received the logs by PM (I think).

4

Do you have the full logs from when this happened? Logs sent only go back to 10/18/2017 03:02 am. Entries you pasted are not in the zip file. If you don’t have the logs can you replicate the issue and send new set of logs with information about what movie you were trying to record and start/end time.

5

Thats a bit strange. I just used PMS to download the set of log files. Not sure why the snippets i posted wouldn’t appear in those logs. As you say, I’ll try to reproduce the issue and post back here with results.

6

OK. Found the relevant log so I’ve PM’d it to you.

7

Thanks for the logs. I did find the entries in the previous zip file you sent. I always try to cut/paste the individual logs into a single file when I analyze the entries. Must have gotten distracted when doing the copy/paste and when I came back to the task thought I had pasted all the individual files.

From looking at the logs and the entries you posted I believe this is the 100% recording issue that others have also posted on the forum regarding. Engineering is working on a solution and from what I recall were looking for Mac users that were experiencing the issue to do some testing.

8

Ah, OK! I’ve just upgraded to 1.9.5 so maybe that’ll fix the problem. If not then I’ll have to wait a while. Thanks for your help.