Pretty new to Plex and so far have not been able to get my schedule working. After some false starts with the Nvidia Shield not having write access to the USB drive, I thought I finally had it all working. Then the first show failed to record. Here is info from the log. Nothing pops out at me initially.
19:58:00.173 [15388] DEBUG - DVR:Grabber: Starting operation for ‘NCIS: Los Angeles - E13 - Cac Tu Nhan’.
Jan 14, 2018 19:58:00.178 [15388] DEBUG - Activity: registered new activity 128a2b2c-43a7-483b-bf0f-18c3e407c935 - Recording
Jan 14, 2018 19:58:00.206 [15388] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10403241 (Silicondust HDHomeRun CONNECT, supported) tuner 0.
Jan 14, 2018 19:58:00.216 [15388] DEBUG - DVR:Subscription: Failed to resolve subscription for ‘guid: com.gracenote.onconnect://show/3561420 thumb: http://tmsimg.plex.tv/assets/p14215795_b_v5_ab.jpg title: NCIS: Los Angeles type: 2 year: 2009’ to library item
Jan 14, 2018 19:58:00.219 [15388] DEBUG - DVR:Grabber: Saving recording to /storage/3CEA-324A/NVIDIA_SHIELD/.grab/a4a0101bc42b08f737ca8f752afe011797945555
Jan 14, 2018 19:58:01.113 [15866] DEBUG - EPG[onconnect]: Next thing to start/end is at 2018-01-15 02:00:00 (in 120 seconds)
Jan 14, 2018 19:58:05.717 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 20.505670 seconds: 192.168.2.63
Jan 14, 2018 19:58:06.712 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.63 (http://192.168.2.63:8088/description)
Jan 14, 2018 19:58:06.712 [15866] DEBUG - HTTP requesting GET http://192.168.2.63:8088/description
Jan 14, 2018 19:58:06.732 [15866] DEBUG - HTTP 200 response from GET http://192.168.2.63:8088/description
Jan 14, 2018 19:58:09.661 [15388] DEBUG - HTTP requesting GET http://192.168.2.227:80/lineup.json
Jan 14, 2018 19:58:09.678 [15388] DEBUG - HTTP 200 response from GET http://192.168.2.227:80/lineup.json
Jan 14, 2018 19:58:09.678 [15388] DEBUG - DVR:Grabber: Going to record for 4011 seconds, final URL is http://192.168.2.227:5004/auto/v42.1
Jan 14, 2018 19:58:09.681 [15388] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘NCIS: Los Angeles - E13 - Cac Tu Nhan’ in 4011 seconds.
Jan 14, 2018 19:58:09.693 [15388] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Jan 14, 2018 19:58:09.693 [15388] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
Jan 14, 2018 19:58:09.693 [15388] ERROR - DVR:Recorder: Error 3 (The recording was aborted) starting the record, shutting things down.
Jan 14, 2018 19:58:09.695 [15388] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jan 14, 2018 19:58:09.695 [15388] ERROR - DVR:Recorder: Error 3 (The recording was aborted) starting the record, shutting things down.
Jan 14, 2018 19:58:09.695 [15388] DEBUG - DVR:Grabber: Operation for NCIS: Los Angeles - E13 - Cac Tu Nhan completed with status error (The recording was aborted)
Jan 14, 2018 19:58:09.695 [15388] DEBUG - Activity: Ended activity 128a2b2c-43a7-483b-bf0f-18c3e407c935.
Jan 14, 2018 19:58:09.696 [15388] ERROR - DVR:Grabber: Starting media grab failed.
Jan 14, 2018 19:59:05.716 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 23.064146 seconds: 192.168.2.63
Jan 14, 2018 19:59:05.716 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 20.235289 seconds: 192.168.2.228
Jan 14, 2018 19:59:05.716 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 23.067966 seconds: 192.168.2.238
Jan 14, 2018 19:59:06.764 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.63 (http://192.168.2.63:8088/description)
Jan 14, 2018 19:59:06.765 [15954] DEBUG - HTTP requesting GET http://192.168.2.63:8088/description
Jan 14, 2018 19:59:06.842 [15954] DEBUG - HTTP 200 response from GET http://192.168.2.63:8088/description
Jan 14, 2018 19:59:07.046 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.238 (http://192.168.2.238:8008/ssdp/device-desc.xml)
Jan 14, 2018 19:59:07.046 [15918] DEBUG - HTTP requesting GET http://192.168.2.238:8008/ssdp/device-desc.xml
Jan 14, 2018 19:59:07.069 [15918] DEBUG - HTTP 200 response from GET http://192.168.2.238:8008/ssdp/device-desc.xml
Jan 14, 2018 19:59:11.280 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.228 (http://192.168.2.228:8060/)
Jan 14, 2018 19:59:11.280 [15917] DEBUG - HTTP requesting GET http://192.168.2.228:8060/
Jan 14, 2018 19:59:11.293 [15917] DEBUG - HTTP 200 response from GET http://192.168.2.228:8060/
Jan 14, 2018 20:00:01.222 [15955] DEBUG - EPG[onconnect]: Next thing to start/end is at 2018-01-15 02:30:00 (in 1800 seconds)
Jan 14, 2018 20:00:04.886 [16024] DEBUG - Statistics: Flushing 1 expired bandwidth entries, 0 expired media entries.
Jan 14, 2018 20:00:35.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 22.255742 seconds: 192.168.2.228
Jan 14, 2018 20:00:40.533 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.228 (http://192.168.2.228:8060/)
Jan 14, 2018 20:00:40.534 [16396] DEBUG - HTTP requesting GET http://192.168.2.228:8060/
Jan 14, 2018 20:00:40.546 [16396] DEBUG - HTTP 200 response from GET http://192.168.2.228:8060/
Jan 14, 2018 20:01:37.502 [16490] DEBUG - Sync: uploadStatus
Jan 14, 2018 20:01:44.759 [7689] DEBUG - EventSource: Failure in ReadData (2 - End of file).
Jan 14, 2018 20:01:44.759 [7689] DEBUG - MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
Jan 14, 2018 20:01:44.759 [7689] ERROR - EventSource: Retrying in 15 seconds.
Jan 14, 2018 20:01:45.693 [7688] DEBUG - handleStreamRead code 335544539: short read
Jan 14, 2018 20:01:45.693 [7688] DEBUG - NotificationStream: Removing because of error
Jan 14, 2018 20:01:59.790 [7689] DEBUG - EventSource: Resolving 45.33.118.95 port 443s
Jan 14, 2018 20:01:59.791 [7689] DEBUG - EventSource: Resolved 45.33.118.95 to 45.33.118.95
Jan 14, 2018 20:01:59.811 [7688] DEBUG - EventSource: Failure in Connect (111 - Connection refused).
Jan 14, 2018 20:01:59.811 [7688] ERROR - EventSource: Retrying in 30 seconds.
Jan 14, 2018 20:02:02.020 [16395] DEBUG - EPG[onconnect]: Purging 20 airings which completed in the past.
Jan 14, 2018 20:02:02.036 [16395] DEBUG - Destroying metadata item 93 (V for Valentine-detta)
Jan 14, 2018 20:02:02.040 [16395] DEBUG - Destroying metadata item 92 (Season 8)
Jan 14, 2018 20:02:02.044 [16395] DEBUG - Destroying metadata item 91 (Bob’s Burgers)
Jan 14, 2018 20:02:02.107 [16395] DEBUG - Destroying metadata item 207 (Episode 10)
Jan 14, 2018 20:02:02.124 [16395] DEBUG - Destroying metadata item 224 (Episode 01-14)
Jan 14, 2018 20:02:02.141 [16395] DEBUG - Destroying metadata item 234 (Under the Influence 3)
Jan 14, 2018 20:02:02.145 [16395] DEBUG - Destroying metadata item 233 (Season 6)
Jan 14, 2018 20:02:02.163 [16395] DEBUG - Destroying metadata item 247 (Family Business)
Jan 14, 2018 20:02:02.167 [16395] DEBUG - Destroying metadata item 246 (Season 22)
Jan 14, 2018 20:02:02.184 [16395] DEBUG - Destroying metadata item 267 (Don’t Bank on Herman)
Jan 14, 2018 20:02:02.202 [16395] DEBUG - Destroying metadata item 278 (Bounty)
Jan 14, 2018 20:02:02.219 [16395] DEBUG - Destroying metadata item 290 (The Tipping Point)
Jan 14, 2018 20:02:02.222 [16395] DEBUG - Destroying metadata item 289 (Season 1)
Jan 14, 2018 20:02:02.226 [16395] DEBUG - Destroying metadata item 288 (Wisdom of the Crowd)
Jan 14, 2018 20:02:02.284 [16395] DEBUG - Destroying metadata item 185 (Episode 01-14)
Jan 14, 2018 20:02:02.357 [16395] DEBUG - Destroying metadata item 320 (Déjà Vu All Over Again)
Jan 14, 2018 20:02:02.376 [16395] DEBUG - Destroying metadata item 340 (You Shook Me)
Jan 14, 2018 20:02:05.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 29.499396 seconds: 192.168.2.63
Jan 14, 2018 20:02:05.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 25.776526 seconds: 192.168.2.182
Jan 14, 2018 20:02:05.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 28.247156 seconds: 192.168.2.228
Jan 14, 2018 20:02:05.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 27.664114 seconds: 192.168.2.238
Jan 14, 2018 20:02:06.723 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.63 (http://192.168.2.63:8088/description)
Jan 14, 2018 20:02:06.724 [16490] DEBUG - HTTP requesting GET http://192.168.2.63:8088/description
Jan 14, 2018 20:02:06.775 [16490] DEBUG - HTTP 200 response from GET http://192.168.2.63:8088/description
Jan 14, 2018 20:02:07.044 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.238 (http://192.168.2.238:8008/ssdp/device-desc.xml)
Jan 14, 2018 20:02:07.044 [16395] DEBUG - HTTP requesting GET http://192.168.2.238:8008/ssdp/device-desc.xml
Jan 14, 2018 20:02:07.063 [16395] DEBUG - HTTP 200 response from GET http://192.168.2.238:8008/ssdp/device-desc.xml
Jan 14, 2018 20:02:07.335 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.182 (http://192.168.2.182:8060/)
Jan 14, 2018 20:02:07.336 [17020] DEBUG - HTTP requesting GET http://192.168.2.182:8060/
Jan 14, 2018 20:02:07.366 [17020] DEBUG - HTTP 200 response from GET http://192.168.2.182:8060/
Jan 14, 2018 20:02:11.600 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.228 (http://192.168.2.228:8060/)
Jan 14, 2018 20:02:11.600 [16395] DEBUG - HTTP requesting GET http://192.168.2.228:8060/
Jan 14, 2018 20:02:11.612 [16395] DEBUG - HTTP 200 response from GET http://192.168.2.228:8060/
Jan 14, 2018 20:02:29.898 [7689] DEBUG - EventSource: Resolving 45.33.118.95 port 443s
Jan 14, 2018 20:02:29.898 [7689] DEBUG - EventSource: Resolved 45.33.118.95 to 45.33.118.95
Jan 14, 2018 20:02:49.998 [7688] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Jan 14, 2018 20:02:54.997 [7688] DEBUG - HTTP requesting GET https://plex.tv/services/pubsub/servers
Jan 14, 2018 20:02:56.132 [7688] DEBUG - HTTP 200 response from GET https://plex.tv/services/pubsub/servers
Jan 14, 2018 20:03:01.136 [7688] DEBUG - PubSubManager: Time to connect to 45.79.197.109 was 128 ms.
Jan 14, 2018 20:03:01.136 [7688] DEBUG - PubSubManager: Time to connect to 173.255.237.43 was 132 ms.
Jan 14, 2018 20:03:01.137 [7688] DEBUG - PubSubManager: Time to connect to 184.105.148.108 was 151 ms.
Jan 14, 2018 20:03:01.137 [7688] DEBUG - PubSubManager: Time to connect to 109.237.24.233 was 253 ms.
Jan 14, 2018 20:03:01.137 [7688] DEBUG - PubSubManager: Time to connect to 139.162.142.209 was 318 ms.
Jan 14, 2018 20:03:01.137 [7688] DEBUG - PubSubManager: Time to connect to 82.94.168.55 was 383 ms.
Jan 14, 2018 20:03:01.137 [7688] DEBUG - PubSubManager: Time to connect to 139.162.115.125 was 767 ms.
Jan 14, 2018 20:03:01.137 [7688] WARN - PubSubManager: Connection to 45.33.118.95 failed: Connection timed out.
Jan 14, 2018 20:03:01.137 [7688] WARN - PubSubManager: Connection to 45.79.10.123 failed: Connection timed out.
Jan 14, 2018 20:03:01.137 [7688] WARN - PubSubManager: Connection to 139.162.7.93 failed: Connection timed out.
Jan 14, 2018 20:03:01.137 [7688] WARN - PubSubManager: Current server (45.33.118.95) failed, we’ll switch.
Jan 14, 2018 20:03:01.156 [7688] DEBUG - EventSource: Stopping.
Jan 14, 2018 20:03:01.157 [7688] DEBUG - EventSource: Resolving 45.79.197.109 port 443s
Jan 14, 2018 20:03:01.157 [7688] DEBUG - PubSubManager: Updating best host to 45.79.197.109.
Jan 14, 2018 20:03:01.157 [7689] DEBUG - EventSource: Resolved 45.79.197.109 to 45.79.197.109
Jan 14, 2018 20:03:01.157 [7688] DEBUG - PubSubManager: Updating best ping time for 45.79.197.109 to 128 ms.
Jan 14, 2018 20:03:01.758 [7689] DEBUG - EventSource: Connected in 558 ms.
Jan 14, 2018 20:03:01.759 [7689] DEBUG - EventSource: Wrote data, reading reply.
Jan 14, 2018 20:03:02.050 [17081] DEBUG - BPQ: onConsiderProcessing: Idle (true)
Jan 14, 2018 20:03:02.050 [17081] DEBUG - BPQ: [Idle] -> [Processing]
Jan 14, 2018 20:03:02.054 [17081] DEBUG - BPQ: generating queue items from 0 generator(s)
Jan 14, 2018 20:03:02.054 [17081] DEBUG - BPQ: generated 0 item(s) for queue
Jan 14, 2018 20:03:02.055 [17081] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Jan 14, 2018 20:03:02.055 [17081] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Jan 14, 2018 20:03:02.059 [17081] DEBUG - BPQ: [Processing] -> [Idle]
Jan 14, 2018 20:03:02.060 [17081] DEBUG - BPQ: garbageCollect - sync - forced - 1
Jan 14, 2018 20:03:02.060 [17081] DEBUG - Sync: starting Sync garbage collection: 1, forced
Jan 14, 2018 20:03:02.060 [17081] DEBUG - Sync: finished Sync garbage collection: 1
Jan 14, 2018 20:03:02.060 [17081] DEBUG - BPQ: garbageCollect - version - forced - -1
Jan 14, 2018 20:03:02.060 [17081] DEBUG - Versions: garbage collecting
Jan 14, 2018 20:03:02.065 [17081] DEBUG - Versions: garbage collected in 0.0 seconds
Jan 14, 2018 20:03:03.499 [7689] DEBUG - EventSource: Read HTTP reply header.
Jan 14, 2018 20:03:03.499 [7689] DEBUG - MyPlex: We appear to have regained Internet connectivity.
Jan 14, 2018 20:03:03.499 [7689] DEBUG - EventSource: Successfully connected to 45.79.197.109.
Jan 14, 2018 20:04:05.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 21.980514 seconds: 192.168.2.63
Jan 14, 2018 20:04:05.715 [7753] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 20.954378 seconds: 192.168.2.182
Jan 14, 2018 20:04:07.362 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.63 (http://192.168.2.63:8088/description)
Jan 14, 2018 20:04:07.362 [17624] DEBUG - HTTP requesting GET http://192.168.2.63:8088/description
Jan 14, 2018 20:04:07.389 [17624] DEBUG - HTTP 200 response from GET http://192.168.2.63:8088/description
Jan 14, 2018 20:04:11.750 [7753] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.2.182 (http://192.168.2.182:8060/)
Jan 14, 2018 20:04:11.751 [17597]