This post relocated from an comment I made on a similar issue. I needed to move this to its own post to not hijack the OP.
Having the same problem with non sports scheduled recordings. I have noticed from time to time that scheduled recordings will disappear from the schedule, but have not looked into why. Tonight it happened with a recording, and I took some time to poor through the logs to try and get to the bottom of things. I started with the Plex Media Server.log and went to to start time of the show that failed to record. There was nothing, no failure or any sign of an attempted start that may have failed. I then searched for the name of the show in the same log and found the scheduler set up the recording on the schedule multiple times today.
First Time - appears successful
Mar 13, 2018 11:15:19.199 [0x7fec6d3fe700] DEBUG - DVR:Schedule: Attempting to schedule the item ‘The Flash - E16 - Run, Iris, Run’.
Mar 13, 2018 11:15:19.199 [0x7fec6d3fe700] DEBUG - DVR:Schedule: Trying airing at 2018-03-13 20:00:00 on channel 65.1.
Mar 13, 2018 11:15:19.199 [0x7fec6d3fe700] DEBUG - DVR:Schedule: Device 0 tuner 1 scheduled recording between 2018-03-13 20:00:00 and 2018-03-13 21:00:00 on channel 65.1.
Mar 13, 2018 11:15:19.199 [0x7fec6d3fe700] DEBUG - DVR:Grabber: Scheduling ‘The Flash - E16 - Run, Iris, Run’ for timed grab at 2018-03-13 20:00:00 (in 31481 seconds)
Next Time - appears successful, notice it is less than a minute after the instance above
Mar 13, 2018 11:16:03.508 [0x7fec683ff700] DEBUG - DVR:Schedule: Attempting to schedule the item ‘The Flash - E16 - Run, Iris, Run’.
Mar 13, 2018 11:16:03.508 [0x7fec683ff700] DEBUG - DVR:Schedule: Trying airing at 2018-03-13 20:00:00 on channel 65.1.
Mar 13, 2018 11:16:03.508 [0x7fec683ff700] DEBUG - DVR:Schedule: Device 0 tuner 1 scheduled recording between 2018-03-13 20:00:00 and 2018-03-13 21:00:00 on channel 65.1.
Mar 13, 2018 11:16:03.508 [0x7fec683ff700] DEBUG - DVR:Grabber: Scheduling ‘The Flash - E16 - Run, Iris, Run’ for timed grab at 2018-03-13 20:00:00 (in 31437 seconds)
Next Time - appears successful, again just after the time above same second
Mar 13, 2018 11:16:03.613 [0x7fec5f3fd700] DEBUG - DVR:Schedule: Attempting to schedule the item ‘The Flash - E16 - Run, Iris, Run’.
Mar 13, 2018 11:16:03.613 [0x7fec5f3fd700] DEBUG - DVR:Schedule: Trying airing at 2018-03-13 20:00:00 on channel 65.1.
Mar 13, 2018 11:16:03.613 [0x7fec5f3fd700] DEBUG - DVR:Schedule: Device 0 tuner 1 scheduled recording between 2018-03-13 20:00:00 and 2018-03-13 21:00:00 on channel 65.1.
Mar 13, 2018 11:16:03.613 [0x7fec5f3fd700] DEBUG - DVR:Grabber: Scheduling ‘The Flash - E16 - Run, Iris, Run’ for timed grab at 2018-03-13 20:00:00 (in 31437 seconds)
Final appearance - the cancellation
Mar 13, 2018 13:35:19.486 [0x7fec563ff700] DEBUG - DVR:Grabber: Cancelling operation for ‘The Flash - E16 - Run, Iris, Run’ with status cancelled.
Mar 13, 2018 13:35:19.486 [0x7fec563ff700] DEBUG - DVR:Grabber: Operation was scheduled, removing timer.
I can attach the full log if asked for it. The DVR is reliable for 80-90% of my recordings, but I would love to figure out why this scenario keeps happening. Any help would be appreciated.
Current version running is: 1.12.0.4829
OS is Ubuntu LTS 16.04
The setup was mostly moved from a Mac Mini after building the dedicated Ubuntu server. I bring this up, because it may help. For some reason, I see the IP from the Mac Mini being referenced all throughout the log when recording requests, completions, etc.
One example out of over 2000 in the log I am in (the server I got the logs for is 192.168.1.40):
Mar 13, 2018 07:30:01.174 [0x7fec82bfe700] DEBUG - Completed: [192.168.1.20:60650] 200 GET /tv.plex.providers.epg.onconnect:2/metadata/com.gracenote.onconnect%3A%2F%2Fshow%2F605685/grandchildren?excludeAllLeaves=1 (10 live) TLS GZIP Page 0-10 36ms 2814 bytes (pipelined: 3)
Thanks again for any help you can provide.
