First I apologize for the long post. Since the last upgrade of Plex Media Server Recording just doesnt work. I have removed the DVR, Added it back, deleted all scheduled recording added them back. I uninstalled plex and reinstalled.
Windows 10 Server.
Version 1.7.6.4058
All Storage locally attached.
HDHomerun Extend
OTA Broadcast Channels.
Log attached. What happens most of the times is the recordings Hang at 100%, I have completely disabled post processing and the problem persist.
I see this. The show Matlock should have completed 11:01 and Remington Steele should have began 10:59. They are on the same channel and nothing else is using the tuner currently. There are 2 errors I see about the Remington Steele Failure. Ironically the Remington Steele Failed with the error “Success”
Jul 20, 2017 10:59:00.960 [28692] ERROR - DVR:Recorder: Error 0 (Success) starting the record, shutting things down.
Jul 20, 2017 10:59:00.961 [28692] DEBUG - DVR:Grabber: Operation for Remington Steele - E20 - Steele in the Chips completed with status error (Success)
Jul 20, 2017 10:59:00.961 [28692] DEBUG - Activity: Ended activity 79e96738-17c0-4c89-8b04-8b7aa55434dd.
Jul 20, 2017 10:59:00.961 [28692] ERROR - DVR:Grabber: Starting media grab failed.
Matlock shows no errors only this
Jul 20, 2017 11:00:58.360 [1324] DEBUG - Destroying metadata item 1178 (Requiem for a Fox)
Jul 20, 2017 11:01:00.975 [1324] DEBUG - DVR:Grabber: Cancelling operation for ‘Matlock - E10 - The Fortune’ with status complete.
Jul 20, 2017 11:01:00.975 [1324] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Jul 20, 2017 11:01:02.052 [21840] DEBUG - Activity: updated activity 8eb363ad-9c61-4d58-93f5-f07750a5052b - completed 100% - Recording
Jul 20, 2017 11:01:55.953 [29588] DEBUG - BPQ: onConsiderProcessing: Idle (true)
Jul 20, 2017 11:01:55.954 [29588] DEBUG - BPQ: [Idle] -> [Processing]
Jul 20, 2017 11:01:55.966 [29588] DEBUG - BPQ: generating queue items from 39 generator(s)
Short of reverting back to a version that worked I am stuck - This latest update simply put for me has been really really bad, and I say that as one who has been using the beta from the beginning and for the most part have had good success and have liked where it has been headed.
HELP would be greatly appreciate. I tried this about a week back and no one from plex has responded to any posted logs though some helpful posters have tried.
Jul 20, 2017 10:58:34.494 [20376] DEBUG - HTTP 200 response from GET https://plex.tv/servers/e9f2667b4ad15790efc68e3104e8687b47d8d2e3/access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Jul 20, 2017 10:58:34.498 [20376] DEBUG - MyPlex: updating with 54 access tokens
Jul 20, 2017 10:58:37.109 [22008] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jul 20, 2017 10:58:37.110 [22008] DEBUG - Auth: authenticated user 1 as BRBMan
Jul 20, 2017 10:58:37.110 [22008] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Jul 20, 2017 10:58:37.111 [28472] DEBUG - Request: [192.168.10.142:36831 (Subnet)] GET / (5 live) TLS GZIP Signed-in Token (BRBMan)
Jul 20, 2017 10:58:37.112 [28472] DEBUG - (Capabilities) Platform ‘Windows’ not matched by plugin platform requirements
Jul 20, 2017 10:58:37.112 [28472] DEBUG - (Capabilities) Platform ‘Windows’ not matched by plugin platform requirements
Jul 20, 2017 10:58:37.115 [22008] DEBUG - Completed: [192.168.10.142:36831] 200 GET / (5 live) TLS GZIP 5ms 1419 bytes (pipelined: 1)
Jul 20, 2017 10:59:00.912 [28692] DEBUG - DVR:Grabber: Starting operation for ‘Remington Steele - E20 - Steele in the Chips’.
Jul 20, 2017 10:59:00.913 [28692] DEBUG - Activity: registered new activity 79e96738-17c0-4c89-8b04-8b7aa55434dd - Recording
Jul 20, 2017 10:59:00.914 [28692] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10532295 tuner 0.
Jul 20, 2017 10:59:00.942 [28692] DEBUG - DVR:Subscription: Resolved subscription to library item ‘Remington Steele’ (180280)
Jul 20, 2017 10:59:00.957 [28692] DEBUG - There were 1 top-level paths for Remington Steele.
Jul 20, 2017 10:59:00.958 [28692] DEBUG - DVR:Grabber: Saving recording to W:\TV-Shows.grab\952512a4d4ae976fa30a414272893c8eb091e902
Jul 20, 2017 10:59:00.959 [28692] DEBUG - DVR:Grabber: Going to record for 3720 seconds, final URL is http://192.168.10.111:5004/auto/v12.2?transcode=none
Jul 20, 2017 10:59:00.959 [28692] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘Remington Steele - E20 - Steele in the Chips’ in 3720 seconds.
Jul 20, 2017 10:59:00.960 [28692] ERROR - DVR:Recorder: Error 0 (Success) starting the record, shutting things down.
Jul 20, 2017 10:59:00.960 [28692] DEBUG - DVR:Recorder: Asked to stop recording ‘Matlock - E10 - The Fortune’.
Jul 20, 2017 10:59:00.960 [28692] DEBUG - DVR:Recorder: Stopping transcode session.
Jul 20, 2017 10:59:00.960 [28692] DEBUG - Job was already killed, not killing again.
Jul 20, 2017 10:59:00.960 [28692] DEBUG - Job was already killed, not killing again.
Jul 20, 2017 10:59:00.960 [28692] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jul 20, 2017 10:59:00.960 [28692] ERROR - DVR:Recorder: Error 0 (Success) starting the record, shutting things down.
Jul 20, 2017 10:59:00.961 [28692] DEBUG - DVR:Grabber: Operation for Remington Steele - E20 - Steele in the Chips completed with status error (Success)
Jul 20, 2017 10:59:00.961 [28692] DEBUG - Activity: Ended activity 79e96738-17c0-4c89-8b04-8b7aa55434dd.
Jul 20, 2017 10:59:00.961 [28692] ERROR - DVR:Grabber: Starting media grab failed.
Jul 20, 2017 10:59:01.640 [22588] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jul 20, 2017 10:59:01.641 [22588] DEBUG - Auth: authenticated user 1 as BRBMan
Jul 20, 2017 10:59:01.641 [22588] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Jul 20, 2017 10:59:01.645 [26660] DEBUG - Request: [192.168.10.142:36855 (Subnet)] GET /media/subscriptions (5 live) TLS GZIP Signed-in Token (BRBMan)
Jul 20, 2017 10:59:01.657 [22588] DEBUG - Completed: [192.168.10.142:36855] 200 GET /media/subscriptions (5 live) TLS GZIP 15ms 1019 bytes (pipelined: 1)
Jul 20, 2017 10:59:01.738 [22008] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jul 20, 2017 10:59:01.739 [22008] DEBUG - Auth: authenticated user 1 as BRBMan
Jul 20, 2017 10:59:01.739 [22008] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Jul 20, 2017 10:59:01.762 [7804] DEBUG - Request: [192.168.10.142:36856 (Subnet)] GET /media/subscriptions/scheduled (5 live) TLS GZIP Signed-in Token (BRBMan)
Jul 20, 2017 10:59:01.842 [22008] DEBUG - Completed: [192.168.10.142:36856] 200 GET /media/subscriptions/scheduled (5 live) TLS GZIP 102ms 11091 bytes (pipelined: 1)
Jul 20, 2017 10:59:10.057 [20376] DEBUG - Activity: updated activity 8eb363ad-9c61-4d58-93f5-f07750a5052b - completed 97% - Recording
Jul 20, 2017 10:59:30.485 [22588] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jul 20, 2017 10:59:30.486 [22588] DEBUG - Auth: authenticated user 1 as BRBMan
Jul 20, 2017 10:59:30.486 [22588] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Jul 20, 2017 10:59:30.491 [26660] DEBUG - Request: [192.168.10.142:36882 (Subnet)] GET /photo/:/transcode?width=130&height=195&minSize=1&url=http%3A%2F%2Ftmsimg.plex.tv%2Fassets%2Fp183937_b_v5_ad.jpg (4 live) TLS GZIP Signed-in Token (BRBMan)
Jul 20, 2017 10:59:30.576 [26660] DEBUG - Photo transcoder: Request for url [tmsimg.plex.tv/assets/p183937_b_v5_ad.jpg] (is local: 0 upscaled: 0)
Jul 20, 2017 10:59:30.708 [26660] DEBUG - The cache file did not exist, but the original did [C:\Users\Ray\AppData\Local\Plex-Server-data\Plex Media Server\Cache\PhotoTranscoder\e6\e69e1983b6d67bdd9e6c8fa687e5b6a90196bda6.jpg].
Jul 20, 2017 10:59:30.732 [26660] DEBUG - Created thumbnail of size 130x195, has pixels: 1
Jul 20, 2017 10:59:30.752 [22588] DEBUG - Completed: [192.168.10.142:36882] 200 GET /photo/:/transcode?width=130&height=195&minSize=1&url=http%3A%2F%2Ftmsimg.plex.tv%2Fassets%2Fp183937_b_v5_ad.jpg (4 live) TLS GZIP 265ms 7748 bytes (pipelined: 1)
Jul 20, 2017 10:59:46.491 [20376] DEBUG - Activity: updated activity 8eb363ad-9c61-4d58-93f5-f07750a5052b - completed 98% - Recording
Jul 20, 2017 11:00:01.419 [28692] DEBUG - EPG[onconnect]: Next thing to start/end is at 2017-07-20 15:30:00 (in 1800 seconds)
Jul 20, 2017 11:00:08.016 [28692] DEBUG - Statistics: Flushing 4 expired bandwidth entries, 0 expired media entries.
Jul 20, 2017 11:00:25.828 [21840] DEBUG - Activity: updated activity 8eb363ad-9c61-4d58-93f5-f07750a5052b - completed 99% - Recording
Jul 20, 2017 11:00:42.406 [16880] DEBUG - NetworkServiceBrowser: PLAYER departed after not being seen for 181.973473 seconds: 192.168.10.140
Jul 20, 2017 11:00:55.448 [1324] DEBUG - EPG[onconnect]: Purging 30 airings which completed in the past.
Jul 20, 2017 11:00:55.636 [1324] DEBUG - Destroying metadata item 706 (Unlikely Suspects)
Jul 20, 2017 11:00:55.768 [1324] DEBUG - Destroying metadata item 705 (Season 2001)
Jul 20, 2017 11:00:56.245 [1324] DEBUG - Destroying metadata item 682 (Episode 96)
Jul 20, 2017 11:00:56.354 [1324] DEBUG - Destroying metadata item 846 (It’s Our Bottom-of-the-Jar Show! Throw an Entire Party With the Last Bits of Everything From Ice Cream to Butter!)
Jul 20, 2017 11:00:56.503 [1324] DEBUG - Destroying metadata item 860 (Margaret Hires a Gardener)
Jul 20, 2017 11:00:56.567 [1324] DEBUG - Destroying metadata item 886 (Episode 07-20)
Jul 20, 2017 11:00:56.649 [1324] DEBUG - Destroying metadata item 900 (The Fortune)
Jul 20, 2017 11:00:56.831 [1324] DEBUG - Destroying metadata item 932 (Sins of Omission)
Jul 20, 2017 11:00:56.925 [1324] DEBUG - Destroying metadata item 946 (Space Rangers; On Shaky Ground)
Jul 20, 2017 11:00:57.366 [1324] DEBUG - Destroying metadata item 971 (Rifflin Hitch Fishing Lodge)
Jul 20, 2017 11:00:57.418 [1324] DEBUG - Destroying metadata item 1010 (Celebration)
Jul 20, 2017 11:00:57.600 [1324] DEBUG - Destroying metadata item 1037 (Without Remorse)
Jul 20, 2017 11:00:57.768 [1324] DEBUG - Destroying metadata item 1053 (Cruel and Unusual Punishment)
Jul 20, 2017 11:00:57.908 [1324] DEBUG - Destroying metadata item 1092 (Episode 54)
Jul 20, 2017 11:00:57.935 [1324] DEBUG - Destroying metadata item 1119 (Episode 07-20)
Jul 20, 2017 11:00:58.013 [1324] DEBUG - Destroying metadata item 1138 (Episode 07-20)
Jul 20, 2017 11:00:58.255 [1324] DEBUG - Destroying metadata item 1166 (Fan Favorites)
Jul 20, 2017 11:00:58.360 [1324] DEBUG - Destroying metadata item 1178 (Requiem for a Fox)
Jul 20, 2017 11:01:00.975 [1324] DEBUG - DVR:Grabber: Cancelling operation for ‘Matlock - E10 - The Fortune’ with status complete.
Jul 20, 2017 11:01:00.975 [1324] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Jul 20, 2017 11:01:02.052 [21840] DEBUG - Activity: updated activity 8eb363ad-9c61-4d58-93f5-f07750a5052b - completed 100% - Recording
Jul 20, 2017 11:01:55.953 [29588] DEBUG - BPQ: onConsiderProcessing: Idle (true)
Jul 20, 2017 11:01:55.954 [29588] DEBUG - BPQ: [Idle] -> [Processing]
Jul 20, 2017 11:01:55.966 [29588] DEBUG - BPQ: generating queue items from 39 generator(s)
Jul 20, 2017 11:01:55.994 [29588] DEBUG - Sync: updating status for sync list 8605341, sync item 14615852, generator 9640
Jul 20, 2017 11:01:56.001 [29588] DEBUG - Sync: updating status for sync list 8605341, sync item 14615857, generator 9641
Jul 20, 2017 11:01:56.004 [29588] DEBUG - Sync: updating status for sync list 8605341, sync item 14615868, generator 9642
Jul 20, 2017 11:01:56.010 [29588] DEBUG - Sync: updating status for sync list 8605341, sync item 14615877, generator 9643
Jul 20, 2017 11:01:56.056 [29588] DEBUG - Sync: updating status for sync list 8605341, sync item 14615883, generator 9644
Jul 20, 2017 11:01:56.080 [29588] DEBUG - Sync: updating status for sync list 8605341, sync item 14615890, generator 9645
Jul 20, 2017 11:01:56.087 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.087 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 10515310, generator 7238
Jul 20, 2017 11:01:56.090 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.090 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 10551728, generator 7252
Jul 20, 2017 11:01:56.092 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.092 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 12839931, generator 8507
Jul 20, 2017 11:01:56.094 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.095 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 12839954, generator 8508
Jul 20, 2017 11:01:56.097 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.097 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 12839970, generator 8509
Jul 20, 2017 11:01:56.101 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.102 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 12965471, generator 8651
Jul 20, 2017 11:01:56.162 [29588] DEBUG - Sync: skipping sync list 8640675 from device Kailey’s iPod because it’s snoozing
Jul 20, 2017 11:01:56.162 [29588] DEBUG - Sync: updating status for sync list 8640675, sync item 15652669, generator 10039
Jul 20, 2017 11:01:56.172 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 18032340, generator 11051
Jul 20, 2017 11:01:56.181 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 18032342, generator 11052
Jul 20, 2017 11:01:56.186 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 18032349, generator 11053
Jul 20, 2017 11:01:56.196 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 18032353, generator 11054
Jul 20, 2017 11:01:56.266 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 19037202, generator 11350
Jul 20, 2017 11:01:56.374 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 19037211, generator 11351
Jul 20, 2017 11:01:56.378 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 19037213, generator 11352
Jul 20, 2017 11:01:56.384 [29588] DEBUG - Sync: updating status for sync list 6224588, sync item 19037215, generator 11353
Jul 20, 2017 11:01:56.388 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 2477331, generator 5607
Jul 20, 2017 11:01:56.392 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 2477343, generator 5608
Jul 20, 2017 11:01:56.398 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 2477374, generator 5609
Jul 20, 2017 11:01:56.402 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 2477384, generator 5610
Jul 20, 2017 11:01:56.419 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 2477393, generator 5611
Jul 20, 2017 11:01:56.423 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 2477414, generator 5612
Jul 20, 2017 11:01:56.428 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 3210950, generator 5613
Jul 20, 2017 11:01:56.436 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934409, generator 5615
Jul 20, 2017 11:01:56.453 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934411, generator 5616
Jul 20, 2017 11:01:56.457 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934418, generator 5617
Jul 20, 2017 11:01:56.462 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934419, generator 5618
Jul 20, 2017 11:01:56.530 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934421, generator 5619
Jul 20, 2017 11:01:56.647 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934424, generator 5620
Jul 20, 2017 11:01:56.757 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934425, generator 5621
Jul 20, 2017 11:01:56.866 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934428, generator 5622
Jul 20, 2017 11:01:56.920 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934437, generator 5624
Jul 20, 2017 11:01:56.930 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 5934442, generator 5625
Jul 20, 2017 11:01:57.012 [29588] DEBUG - Sync: updating status for sync list 1921738, sync item 6273703, generator 5626
Jul 20, 2017 11:01:57.090 [29588] DEBUG - BPQ: generated 0 item(s) for queue
Jul 20, 2017 11:01:57.091 [29588] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Jul 20, 2017 11:01:57.091 [29588] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Jul 20, 2017 11:01:57.095 [29588] DEBUG - BPQ: [Processing] -> [Idle]
Jul 20, 2017 11:01:57.095 [29588] DEBUG - BPQ: garbageCollect - sync - forced - 1
Jul 20, 2017 11:01:57.095 [29588] DEBUG - Sync: starting Sync garbage collection: 1, forced
Jul 20, 2017 11:01:57.096 [29588] DEBUG - Sync: garbage collecting database for sync list 8605341
Jul 20, 2017 11:01:57.112 [29588] DEBUG - Sync: garbage collected database for sync list 8605341 in 0.0 seconds
Jul 20, 2017 11:01:57.113 [29588] DEBUG - Sync: garbage collecting database for sync list 8640675
Jul 20, 2017 11:01:57.198 [29588] DEBUG - Sync: garbage collected database for sync list 8640675 in 0.1 seconds
Jul 20, 2017 11:01:57.198 [29588] DEBUG - Sync: garbage collecting database for sync list 6224588
Jul 20, 2017 11:01:57.276 [29588] DEBUG - Sync: garbage collected database for sync list 6224588 in 0.1 seconds
Jul 20, 2017 11:01:57.276 [29588] DEBUG - Sync: garbage collecting database for sync list 1921738
Jul 20, 2017 11:01:57.688 [29588] DEBUG - Sync: garbage collected database for sync list 1921738 in 0.4 seconds
Jul 20, 2017 11:01:57.688 [29588] DEBUG - Sync: finished Sync garbage collection: 1
Jul 20, 2017 11:01:57.688 [29588] DEBUG - BPQ: garbageCollect - version - forced - -1
Jul 20, 2017 11:01:57.688 [29588] DEBUG - Versions: garbage collecting
Jul 20, 2017 11:01:57.724 [29588] DEBUG - Versions: garbage collected in 0.0 seconds
