Server Version#: 1.15.1.710 on Mac mini (Late 2012)
Player Version#: 1.39 on Apple TV 4
My PMS is working well but it stubbornly refuses to record “Die purpurnen Flüsse”, also know as “The Crimson Rivers” or “Les Rivières Purpres” from the UK channel More4+1 (Freesat).
It allows me to schedule the recordings, tries to record but then fails.
I have full set of logs showing the failure. Here’s an extract showing the failed attempt of last FRI:
Mar 01, 2019 22:00:00.538 [0x70000c593000] DEBUG - DVR:Grabber: Starting operation for 'Die purpurnen Flüsse - E8 - Songs of Darkness, Part 2' on channel 125.
Mar 01, 2019 22:00:00.542 [0x70000c593000] DEBUG - Activity: registered new activity 31c66027-8b7d-4158-9ef9-42e695574a76 - Recording
Mar 01, 2019 22:00:00.542 [0x70000c593000] DEBUG - DVR:Grabber: Remote starting a media grab on device device://tv.plex.grabbers.tunerservice/dvb%23sat2ip%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f (Elgato Systems GmbH EyeTV Netstream 4Sat, supported) tuner 3.
Mar 01, 2019 22:00:00.542 [0x70000bf6f000] DEBUG - HTTP requesting GET http://127.0.0.1:32600/devices/dvb%23sat2ip%230%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f
Mar 01, 2019 22:00:00.545 [0x70000c593000] DEBUG - DVR:Subscription: Failed to resolve subscription for show 'guid: com.gracenote.onconnect://show/15847748 thumb: https://image.tmdb.org/t/p/w154/ahVy85IlUQagmFkQrJxiJE8ZMC4.jpg title: Die purpurnen Flüsse type: 2 year: 2018' to library item
Mar 01, 2019 22:00:00.546 [0x70000c593000] DEBUG - DVR:Grabber: checking for 8874 MB of available disk space in grab path and transcode cache path
Mar 01, 2019 22:00:00.547 [0x70000af92000] DEBUG - Auth: authenticated user 1 as mw4925
Mar 01, 2019 22:00:00.548 [0x70000b015000] DEBUG - Request: [192.168.1.106:57633 (Subnet)] GET /media/subscriptions/scheduled (11 live) TLS GZIP Signed-in Token (mw4925)
Mar 01, 2019 22:00:00.561 [0x70000af92000] DEBUG - Completed: [192.168.1.106:57633] 200 GET /media/subscriptions/scheduled (12 live) TLS GZIP 13ms 9856 bytes (pipelined: 2)
Mar 01, 2019 22:00:00.572 [0x70000af0f000] DEBUG - Auth: authenticated user 1 as mw4925
Mar 01, 2019 22:00:00.572 [0x70000abfd000] DEBUG - Request: [192.168.1.106:57634 (Subnet)] GET /media/subscriptions?includeGrabs=1 (11 live) TLS GZIP Signed-in Token (mw4925)
Mar 01, 2019 22:00:00.579 [0x70000bf6f000] DEBUG - HTTP 200 response from GET http://127.0.0.1:32600/devices/dvb%23sat2ip%230%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f
Mar 01, 2019 22:00:00.582 [0x70000af0f000] DEBUG - Completed: [192.168.1.106:57634] 200 GET /media/subscriptions?includeGrabs=1 (11 live) TLS GZIP 9ms 7605 bytes (pipelined: 1)
Mar 01, 2019 22:00:00.641 [0x70000c593000] DEBUG - DVR:Grabber: Saving recording to "/Volumes/mini_hd/media/tv/.grab/24d1164eec46c556edca47ec09027f2da5a80782"
Mar 01, 2019 22:00:00.719 [0x70000c593000] DEBUG - DVR:Grabber: Going to record for 3900 seconds, final URL is http://127.0.0.1:32600/devices/dvb%23sat2ip%233%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f/media/triplet%3A%2F%2F2%3A2041%3A9230?param=%3C%3Fxml%20version%3D%221%2E0%22%20encoding%3D%22UTF-8%22%3F%3E%0A%3Ctunedata%3E%3Ctt%3E1%3C%2Ftt%3E%3Cdq%3E0%3C%2Fdq%3E%3Cdr%2F%3E%3Cfr%3E10714000%3C%2Ffr%3E%3Cmd%3E0%3C%2Fmd%3E%3Csr%3E22000000%3C%2Fsr%3E%3Cpl%3E0%3C%2Fpl%3E%3Clf%3E9750000%3C%2Flf%3E%3Cl1%3E9750000%3C%2Fl1%3E%3Cl2%3E10600000%3C%2Fl2%3E%3Cls%3E11700000%3C%2Fls%3E%3Cpp%3E0%3C%2Fpp%3E%3Chz%3E0%3C%2Fhz%3E%3Cin%3E0%3C%2Fin%3E%3Cfc%3E86%3C%2Ffc%3E%3Ct%3E2041%3C%2Ft%3E%3Cn%3E2%3C%2Fn%3E%3Cs%3E9230%3C%2Fs%3E%3Cen%3E0%3C%2Fen%3E%3C%2Ftunedata%3E%0A
Mar 01, 2019 22:00:00.721 [0x70000c593000] DEBUG - MediaRecorderVirtual: setting stop time to 2019-03-01 23:05:00
Mar 01, 2019 22:00:00.721 [0x70000c593000] DEBUG - DVR:Segmenter: Creating a new recorder for http://127.0.0.1:32600/devices/dvb%23sat2ip%233%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f/media/triplet%3A%2F%2F2%3A2041%3A9230?param=%3C%3Fxml%20version%3D%221%2E0%22%20encoding%3D%22UTF-8%22%3F%3E%0A%3Ctunedata%3E%3Ctt%3E1%3C%2Ftt%3E%3Cdq%3E0%3C%2Fdq%3E%3Cdr%2F%3E%3Cfr%3E10714000%3C%2Ffr%3E%3Cmd%3E0%3C%2Fmd%3E%3Csr%3E22000000%3C%2Fsr%3E%3Cpl%3E0%3C%2Fpl%3E%3Clf%3E9750000%3C%2Flf%3E%3Cl1%3E9750000%3C%2Fl1%3E%3Cl2%3E10600000%3C%2Fl2%3E%3Cls%3E11700000%3C%2Fls%3E%3Cpp%3E0%3C%2Fpp%3E%3Chz%3E0%3C%2Fhz%3E%3Cin%3E0%3C%2Fin%3E%3Cfc%3E86%3C%2Ffc%3E%3Ct%3E2041%3C%2Ft%3E%3Cn%3E2%3C%2Fn%3E%3Cs%3E9230%3C%2Fs%3E%3Cen%3E0%3C%2Fen%3E%3C%2Ftunedata%3E%0A.
Mar 01, 2019 22:00:00.728 [0x70000c593000] DEBUG - DVR:Grabber: Waiting for a tuner on device://tv.plex.grabbers.tunerservice/dvb%23sat2ip%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f (4 available) for at most 3900 seconds.
Mar 01, 2019 22:00:00.728 [0x70000c593000] DEBUG - DVR:Grabber: Allocated a tuner on device://tv.plex.grabbers.tunerservice/dvb%23sat2ip%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f (3 left)
Mar 01, 2019 22:00:00.728 [0x70000c593000] DEBUG - We're going to try to auto-select an audio stream for account 1.
Mar 01, 2019 22:00:00.728 [0x70000c593000] DEBUG - Selecting best audio stream for part ID -1 (autoselect: 1 language: en)
Mar 01, 2019 22:00:00.728 [0x70000c593000] DEBUG - We're going to try to auto-select a subtitle.
Mar 01, 2019 22:00:00.729 [0x70000c593000] DEBUG - Audio Stream: -1, Subtitle Stream: -1
Mar 01, 2019 22:00:00.730 [0x70000c593000] DEBUG - MDE: Selected protocol hls; container: mpegts
Mar 01, 2019 22:00:00.730 [0x70000c593000] ERROR - Unable to find title for item of type 5
Mar 01, 2019 22:00:00.730 [0x70000c593000] DEBUG - MDE: analyzing media item -1
Mar 01, 2019 22:00:00.730 [0x70000c593000] DEBUG - MDE: : no direct play video profile exists for http/mpegts/
Mar 01, 2019 22:00:00.730 [0x70000c593000] DEBUG - MDE: : no direct play video profile exists for http/mpegts//
Mar 01, 2019 22:00:00.730 [0x70000c593000] DEBUG - MDE: : codec is unavailable for analysis
Mar 01, 2019 22:00:00.730 [0x70000c593000] DEBUG - MDE: : codec is unavailable for analysis
Mar 01, 2019 22:00:00.731 [0x70000c593000] ERROR - Unable to find title for item of type 5
Mar 01, 2019 22:00:00.731 [0x70000c593000] DEBUG - MDE: : selected media 0 / -1
Mar 01, 2019 22:00:00.731 [0x70000c593000] DEBUG - Cleaning directory for session a169a6be-e70b-49be-8840-5563ea3fb625 ()
Mar 01, 2019 22:00:00.731 [0x70000c593000] DEBUG - Starting a transcode session a169a6be-e70b-49be-8840-5563ea3fb625 at offset -1.0 (state=3)
Mar 01, 2019 22:00:00.731 [0x70000c593000] DEBUG - Streaming Resource: Added session 0x7f7f969db190:a169a6be-e70b-49be-8840-5563ea3fb625
Mar 01, 2019 22:00:00.734 [0x70000c593000] DEBUG - TPU: hardware transcoding: enabled, but no hardware decode accelerator found
Mar 01, 2019 22:00:00.734 [0x70000c593000] DEBUG - TPU: hardware transcoding: final decoder: , final encoder:
Mar 01, 2019 22:00:00.737 [0x70000c593000] DEBUG - Job running: EAE_ROOT='/var/folders/hd/c4g22h9d68554571y7lc5cwh0000gq/T/pms-ef5183ac-a345-499d-a3d8-30373916763b/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/Users/plex/Library/Application\ Support/Plex\ Media\ Server/Codecs/a22632d-2034-darwin-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/Applications/Plex Media Server.app/Contents/MacOS/Plex Transcoder' '-noaccurate_seek' '-ignore_unknown' '-scan_all_pmts' '-1' '-rw_timeout' '30000000' '-reconnect' '1' '-reconnect_streamed' '1' '-reconnect_delay_max' '30' '-fflags' '+discardcorruptts+fillwallclockdts' '-probesize' '10000000' '-i' 'http://127.0.0.1:32600/devices/dvb%23sat2ip%233%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f/media/triplet%3A%2F%2F2%3A2041%3A9230?param=%3C%3Fxml%20version%3D%221%2E0%22%20encoding%3D%22UTF-8%22%3F%3E%0A%3Ctunedata%3E%3Ctt%3E1%3C%2Ftt%3E%3Cdq%3E0%3C%2Fdq%3E%3Cdr%2F%3E%3Cfr%3E10714000%3C%2Ffr%3E%3Cmd%3E0%3C%2Fmd%3E%3Csr%3E22000000%3C%2Fsr%3E%3Cpl%3E0%3C%2Fpl%3E%3Clf%3E9750000%3C%2Flf%3E%3Cl1%3E9750000%3C%2Fl1%3E%3Cl2%3E10600000%3C%2Fl2%3E%3Cls%3E11700000%3C%2Fls%3E%3Cpp%3E0%3C%2Fpp%3E%3Chz%3E0%3C%2Fhz%3E%3Cin%3E0%3C%2Fin%3E%3Cfc%3E86%3C%2Ffc%3E%3Ct%3E2041%3C%2Ft%3E%3Cn%3E2%3C%2Fn%3E%3Cs%3E9230%3C%2Fs%3E%3Cen%3E0%3C%2Fen%3E%3C%2Ftunedata%3E%0A' '-map' '0:V?' '-codec:V' 'copy' '-map' '0:a?' '-codec:a' 'copy' '-copypriorss:a' '0' '-map' '0:s?' '-codec:s' 'copy' '-break_non_keyframes' '1' '-segment_format' 'mpegts' '-f' 'ssegment' '-individual_header_trailer' '0' '-segment_time' '1' '-segment_start_number' '0' '-segment_time_delta' '0.25' '-segment_list' 'http://127.0.0.1:32400/video/:/transcode/session/a169a6be-e70b-49be-8840-5563ea3fb625/4d7c3caa-66d4-4243-baed-ef5d6480533a/seglist' '-segment_list_type' 'csv' '-segment_list_size' '2147483647' '-segment_list_separate_stream_times' '1' '-max_delay' '5000000' '-map_metadata' '-1' '-map_chapters' '-1' 'media-%05d.ts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-xioerror' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/a169a6be-e70b-49be-8840-5563ea3fb625/4d7c3caa-66d4-4243-baed-ef5d6480533a/progress'
Mar 01, 2019 22:00:00.738 [0x70000c593000] DEBUG - Jobs: Starting child process with pid 55201
Mar 01, 2019 22:00:00.789 [0x70000aa74000] DEBUG - Request: [127.0.0.1:64405 (Loopback)] PUT /video/:/transcode/session/a169a6be-e70b-49be-8840-5563ea3fb625/4d7c3caa-66d4-4243-baed-ef5d6480533a/progress?status=startup (12 live) Signed-in Token (mw4925)
Mar 01, 2019 22:00:00.790 [0x70000af0f000] DEBUG - Completed: [127.0.0.1:64405] 204 PUT /video/:/transcode/session/a169a6be-e70b-49be-8840-5563ea3fb625/4d7c3caa-66d4-4243-baed-ef5d6480533a/progress?status=startup (12 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-)
Mar 01, 2019 22:00:00.790 [0x70000b015000] DEBUG - Request: [127.0.0.1:64405 (Loopback)] PUT /video/:/transcode/session/a169a6be-e70b-49be-8840-5563ea3fb625/4d7c3caa-66d4-4243-baed-ef5d6480533a/progress?status=opening (12 live) Signed-in Token (mw4925)
Mar 01, 2019 22:00:00.790 [0x70000af92000] DEBUG - Completed: [127.0.0.1:64405] 204 PUT /video/:/transcode/session/a169a6be-e70b-49be-8840-5563ea3fb625/4d7c3caa-66d4-4243-baed-ef5d6480533a/progress?status=opening (12 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-)
Mar 01, 2019 22:00:01.017 [0x70000af0f000] DEBUG - Auth: authenticated user 1 as mw4925
Mar 01, 2019 22:00:01.017 [0x70000aa74000] DEBUG - Request: [192.168.1.106:57633 (Subnet)] GET /tv.plex.providers.epg.onconnect:8/hubs/discover?count=50&includeCollections=1&includeExternalMetadata=1&includeLibraryPlaylists=1&includeStations=1&includeTrailers=1&includeTypeFirst=0 (12 live) TLS GZIP Signed-in Token (mw4925)
Mar 01, 2019 22:00:01.017 [0x70000af92000] DEBUG - Auth: authenticated user 1 as mw4925
Mar 01, 2019 22:00:01.018 [0x70000abfd000] DEBUG - Request: [192.168.1.106:57634 (Subnet)] GET /tv.plex.providers.epg.onconnect:8/hubs/discover?count=50&includeCollections=1&includeExternalMetadata=1&includeLibraryPlaylists=1&includeStations=1&includeTrailers=1&includeTypeFirst=0 (12 live) TLS GZIP Signed-in Token (mw4925)
Mar 01, 2019 22:00:01.025 [0x70000af92000] DEBUG - Auth: authenticated user 1 as mw4925
Mar 01, 2019 22:00:01.025 [0x70000b8c8000] DEBUG - Request: [192.168.1.106:57635 (Subnet)] GET /tv.plex.providers.epg.onconnect:8/hubs/discover?count=50&includeCollections=1&includeExternalMetadata=1&includeLibraryPlaylists=1&includeStations=1&includeTrailers=1&includeTypeFirst=0 (13 live) TLS GZIP Signed-in Token (mw4925)
Mar 01, 2019 22:00:01.032 [0x70000bb57000] DEBUG - EPG[onconnect]: Next thing to start/end is at 2019-03-01 22:25:00 GMT (in 1500 seconds)
Mar 01, 2019 22:00:01.426 [0x70000b015000] ERROR - [Transcoder] http://127.0.0.1:32600/devices/dvb%23sat2ip%233%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f/media/triplet%3A%2F%2F2%3A2041%3A9230?param=%3C%3Fxml%20version%3D%221%2E0%22%20encoding%3D%22UTF-8%22%3F%3E%0A%3Ctunedata%3E%3Ctt%3E1%3C%2Ftt%3E%3Cdq%3E0%3C%2Fdq%3E%3Cdr%2F%3E%3Cfr%3E10714000%3C%2Ffr%3E%3Cmd%3E0%3C%2Fmd%3E%3Csr%3E22000000%3C%2Fsr%3E%3Cpl%3E0%3C%2Fpl%3E%3Clf%3E9750000%3C%2Flf%3E%3Cl1%3E9750000%3C%2Fl1%3E%3Cl2%3E10600000%3C%2Fl2%3E%3Cls%3E11700000%3C%2Fls%3E%3Cpp%3E0%3C%2Fpp%3E%3Chz%3E0%3C%2Fhz%3E%3Cin%3E0%3C%2Fin%3E%3Cfc%3E86%3C%2Ffc%3E%3Ct%3E2041%3C%2Ft%3E%3Cn%3E2%3C%2Fn%3E%3Cs%3E9230%3C%2Fs%3E%3Cen%3E0%3C%2Fen%3E%3C%2Ftunedata%3E%0A: Server returned 404 Not Found
Mar 01, 2019 22:00:01.428 [0x70000ae09000] DEBUG - Jobs: '/Applications/Plex Media Server.app/Contents/MacOS/Plex Transcoder' exit code for process 55201 is 1 (failure)
Mar 01, 2019 22:00:01.428 [0x70000c593000] DEBUG - TranscodeSession: session failed while waiting for duration
Mar 01, 2019 22:00:01.428 [0x70000c593000] ERROR - Failed to start session.
Mar 01, 2019 22:00:01.428 [0x70000c0f8000] DEBUG - Streaming Resource: Terminated session 0x7f7f969db190:a169a6be-e70b-49be-8840-5563ea3fb625 with reason Recording failed. Please check your tuner or antenna.
Mar 01, 2019 22:00:01.428 [0x70000bff2000] DEBUG - Killing job.
Mar 01, 2019 22:00:01.428 [0x70000c593000] ERROR - DVR:Recorder: Unable to create transcode session or session failed to start.
Mar 01, 2019 22:00:01.428 [0x70000bff2000] DEBUG - Signalling job ID 55201 with 9
Mar 01, 2019 22:00:01.428 [0x70000bff2000] DEBUG - Job was already killed, not killing again.
Mar 01, 2019 22:00:01.428 [0x70000c593000] DEBUG - Job was already killed, not killing again.
Mar 01, 2019 22:00:01.428 [0x70000bff2000] DEBUG - Stopping transcode session a169a6be-e70b-49be-8840-5563ea3fb625
Mar 01, 2019 22:00:01.429 [0x70000c593000] ERROR - DVR:Recorder: Error 16 (Recording failed. Please check your tuner or antenna.) starting the record, shutting things down.
Mar 01, 2019 22:00:01.429 [0x70000bbda000] DEBUG - Cleaning directory for session a169a6be-e70b-49be-8840-5563ea3fb625 (/Users/plex/Library/Caches/PlexMediaServer/Transcode/Sessions/plex-transcode-a169a6be-e70b-49be-8840-5563ea3fb625)
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - MediaRecorderVirtual: setting stop time to 2019-03-01 22:00:01
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - DVR:Recorder: Asked to stop recording 'Die purpurnen Flüsse - E8 - Songs of Darkness, Part 2' on channel 125.
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - DVR:Grabber: Freed a tuner on device://tv.plex.grabbers.tunerservice/dvb%23sat2ip%23uuid%3a546f6d62-000c-6c05-0ebc-656c6761746f (now 4 available)
Mar 01, 2019 22:00:01.429 [0x70000c593000] ERROR - DVR:Recorder: Error 16 (Recording failed. Please check your tuner or antenna.) starting the record, shutting things down.
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - MediaRecorderVirtual: setting stop time to 2019-03-01 22:00:01
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - DVR:Recorder: No more consumers, stopping.
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - DVR:Grabber: Operation for 'Die purpurnen Flüsse - E8 - Songs of Darkness, Part 2' on channel 125 completed with status error (Recording failed. Please check your tuner or antenna.)
Mar 01, 2019 22:00:01.429 [0x70000c593000] DEBUG - Activity: Ended activity 31c66027-8b7d-4158-9ef9-42e695574a76.
Mar 01, 2019 22:00:01.429 [0x70000c593000] ERROR - DVR:Grabber: Starting media grab failed.
Mar 01, 2019 22:00:01.433 [0x70000bff2000] DEBUG - Transcoder: Cleaning old transcode directories.
