So far my experience with Plex has not been a good one. I set up a server and am trying Plex pass to record the Olympics. In three days it has managed to record 48 minutes. For the first day the problem was write permissions on the SMB share. That is now fixed and things still aren’t working right. The biggest problem is there is nowhere that actually tells me there is a problem or what the problem is. I’m really glad I’m on a free trial and haven’t actually paid for this. Is there a way to actually get this working?
Without knowing more information about your configuration my first recommendation would be to record to a local drive after recording you can setup some process to move it to your network share if that is where you ultimately want recordings to reside. You can configure the Library you are recording to with multiple folders, one being your network share another a local folder. When you setup a recording to a library with multiple folders you will get one additional dropdown selection to specify where to record to. If you try this option out I would suggest deleting the current recording and recreate it, Plex tends to keep hold of the prior recording location even if changed on the recording at a later date.
The Plex Media Server log file should have information on why recordings fail. I would also try to ensure you are on the latest Plex Pass version since there have been several releases why attempts to address recording failures released since the current Public version.
The Plex Server is 1.10.1.4602 and is running on a Ubuntu 16.04 VM hosted on ESXi with 4GB of RAM, 14 vCPUs of a E5-2650v2. The OS drive is 40GB and the media is hosted on a Windows 2012 R2 server and are SMB shares.
Which log file would the info be in and what am I looking for. There is a ton of stuff in the zip file I got off the server.
I’ve now upgraded to Version 1.11.2.4772.
The Plex Media Server log files contain information about recordings.
I found the log file, but what am I looking for? The current log is 40135 lines, and it covers less than 2 minutes. I need to know what to search for. And is something wrong with the server or the logging? Most of the entries look like this.
Feb 12, 2018 17:44:03.095 [0x7fadb23ff700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Look for the show. There are 6 Plex Media Server Log Files. If your log only covers 2 minutes I will not hold out much hope that it will contain much information about what happened with a show.
I found this. Which looks liek the correct info.
Feb 12, 2018 09:16:30.889 [0x7fadb5fff700] DEBUG - DVR:Schedule: Device 0 tuner 0 scheduled recording between 2018-02-24 11:27:00 and 2018-02-24 13:33:00 on channel 13.1.
Finally I get this, two hours late.
Feb 12, 2018 13:58:00.046 [0x7fadb37ff700] DEBUG - DVR:Grabber: Starting operation for ‘2018 Winter Olympics - Freestyle Skiing, Ski Jumping, Luge’.
Feb 12, 2018 13:58:00.047 [0x7fadb37ff700] DEBUG - Activity: registered new activity 76623aa5-7e20-4fe6-a243-5849a729b75b - Recording
Feb 12, 2018 13:58:00.048 [0x7fadb37ff700] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10412402 (Silicondust HDHomeRun CONNECT, supported) tuner 0.
Finally I get this.
Feb 12, 2018 14:13:31.266 [0x7fadb37ff700] ERROR - Failed to calculate available disk space for path ‘/home/phil/media/tv/.grab’: 1 (Operation not permitted)
Feb 12, 2018 14:13:31.266 [0x7fadb37ff700] DEBUG - DVR:Grabber: Saving recording to /home/phil/media/tv/.grab/96169826443aee69632790e561f2124e778dfb73
Feb 12, 2018 14:13:31.267 [0x7fadb37ff700] ERROR - IsDirectory failed boost::filesystem::status: Permission denied: “/home/phil/media/tv/.grab/96169826443aee69632790e561f2124e778dfb73”
Feb 12, 2018 14:13:31.270 [0x7fadb37ff700] ERROR - DVR:Grabber: No write permission.
Feb 12, 2018 14:13:31.271 [0x7fadb37ff700] DEBUG - DVR:Grabber: Operation for 2018 Winter Olympics - Freestyle Skiing, Ski Jumping, Luge completed with status error (No write access to destination)
Feb 12, 2018 14:13:31.271 [0x7fadb37ff700] DEBUG - Activity: Ended activity 76623aa5-7e20-4fe6-a243-5849a729b75b.
Feb 12, 2018 14:13:31.271 [0x7fadb37ff700] ERROR - DVR:Grabber: Starting media grab failed.
Then there’s this mess for the most recent attempt.
Feb 12, 2018 18:58:00.152 [0x7fad90bff700] DEBUG - DVR:Grabber: Starting operation for ‘2018 Winter Olympics - Alpine Skiing, Snowboarding, Speed Skating’.
Feb 12, 2018 18:58:00.153 [0x7fad90bff700] DEBUG - Activity: registered new activity 77d97dc4-247f-4d19-a885-96cfd3313f64 - Recording
Feb 12, 2018 18:58:00.153 [0x7fad90bff700] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10412402 (Silicondust HDHomeRun CONNECT, supported) tuner 0.
Feb 12, 2018 18:58:00.154 [0x7fadb37ff700] DEBUG - Thread: Running async task started by thread 0x7fad90bff700.
Feb 12, 2018 18:58:00.157 [0x7fad90bff700] DEBUG - DVR:Subscription: Resolved subscription to library item ‘2018 Winter Olympics’ (10127)
Feb 12, 2018 18:58:00.159 [0x7fad90bff700] DEBUG - There were 1 top-level paths for 2018 Winter Olympics.
Feb 12, 2018 18:58:00.210 [0x7fad90bff700] DEBUG - DVR:Grabber: Saving recording to /home/phil/media/tv/.grab/60c9fb61a09548b0d45d761de3730e8e22eebe06
Feb 12, 2018 18:58:00.214 [0x7fad90bff700] DEBUG - HTTP requesting GET http://192.168.10.2:80/lineup.json
Feb 12, 2018 18:58:00.280 [0x7fad90bff700] DEBUG - HTTP 200 response from GET http://192.168.10.2:80/lineup.json
Feb 12, 2018 18:58:00.282 [0x7fad90bff700] DEBUG - DVR:Grabber: Going to record for 12840 seconds, final URL is http://192.168.10.2:5004/auto/v13.1
Feb 12, 2018 18:58:00.283 [0x7fad90bff700] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘2018 Winter Olympics - Alpine Skiing, Snowboarding, Speed Skating’ in 12840 seconds.
Feb 12, 2018 18:58:00.284 [0x7fad90bff700] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.10.2:5004/auto/v13.1.
Feb 12, 2018 18:58:00.287 [0x7fad90bff700] DEBUG - DVR:Grabber: Waiting for a tuner (3 available).
Feb 12, 2018 18:58:00.287 [0x7fad90bff700] DEBUG - DVR:Grabber: Allocated a tuner (2 left)
Feb 12, 2018 18:58:00.288 [0x7fad90bff700] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Feb 12, 2018 18:58:00.288 [0x7fad90bff700] DEBUG - Selecting best audio stream for part ID -1 (autoselect: 0 language: en)
Feb 12, 2018 18:58:00.288 [0x7fad90bff700] DEBUG - Audio Stream: -1, Subtitle Stream: -1
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: Selected protocol hls; container: mpegts
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] ERROR - Unable to find title for item of type 5
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: analyzing media item -1
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: : no direct play video profile exists for http/mpegts/
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: : no direct play video profile exists for http/mpegts//
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: : codec is unavailable for analysis
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: : codec is unavailable for analysis
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] ERROR - Unable to find title for item of type 5
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - MDE: : selected media 0 / -1
Feb 12, 2018 18:58:00.290 [0x7fad90bff700] DEBUG - Cleaning directory for session 8c4ec87b-027f-4450-be46-99bd10d44048 ()
Feb 12, 2018 18:58:00.292 [0x7fad90bff700] DEBUG - Starting a transcode session 8c4ec87b-027f-4450-be46-99bd10d44048 at offset -1.0 (state=3)
Feb 12, 2018 18:58:00.292 [0x7fad90bff700] DEBUG - Streaming Resource: Added session 0x7fada3c1fb60:8c4ec87b-027f-4450-be46-99bd10d44048
Feb 12, 2018 18:58:00.294 [0x7fad90bff700] DEBUG - Job running: EAE_ROOT=’/tmp/pms-89c1b3d6-68bd-4ab0-9fec-5b06b23ada3b/EasyAudioEncoder’ FFMPEG_EXTERNAL_LIBS=’/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/6bd6751-1276-linux-ubuntu-x86_64/’ XDG_CACHE_HOME=’/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/’ XDG_DATA_HOME=’/usr/lib/plexmediaserver/Resources/’ X_PLEX_TOKEN=‘xxxxxxxxxxxxxxxxxxxx’ ‘/usr/lib/plexmediaserver/Plex Transcoder’ ‘-noaccurate_seek’ ‘-ignore_unknown’ ‘-scan_all_pmts’ ‘-1’ ‘-rw_timeout’ ‘30000000’ ‘-fflags’ ‘+discardcorruptts+fillwallclockdts’ ‘-i’ ‘http://192.168.10.2:5004/auto/v13.1’ ‘-map’ ‘0:V?’ ‘-codec:V’ ‘copy’ ‘-map’ ‘0:a?’ ‘-codec:a’ ‘copy’ ‘-copypriorss:a’ ‘0’ ‘-map’ ‘0:s?’ ‘-codec:s’ ‘copy’ ‘-segment_format’ ‘mpegts’ ‘-f’ ‘ssegment’ ‘-individual_header_trailer’ ‘0’ ‘-segment_time’ ‘1’ ‘-segment_start_number’ ‘0’ ‘-segment_time_delta’ ‘0.0625’ ‘-segment_list’ ‘http://127.0.0.1:32400/video/:/transcode/session/8c4ec87b-027f-4450-be46-99bd10d44048/7438b729-4679-4cbb-be88-a421eccdf36f/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’ ‘-progressurl’ ‘http://127.0.0.1:32400/video/:/transcode/session/8c4ec87b-027f-4450-be46-99bd10d44048/7438b729-4679-4cbb-be88-a421eccdf36f/progress’
Feb 12, 2018 18:58:00.405 [0x7fad9a7ff700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Feb 12, 2018 18:58:00.405 [0x7fad9a7ff700] DEBUG - Auth: Refreshing tokens inside the token-based authentication filter.
Feb 12, 2018 18:58:00.405 [0x7fad983ff700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Feb 12, 2018 18:58:00.405 [0x7fad9a7ff700] DEBUG - HTTP requesting GET https://plex.tv/servers/60d78e39e03d45155d1af4ffb582250f85e8c361/access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Feb 12, 2018 18:58:00.406 [0x7fad983ff700] ERROR - [Transcoder] http://192.168.10.2:5004/auto/v13.1: Server returned 5XX Server Error reply
Feb 12, 2018 18:58:00.407 [0x7fadb0fff700] ERROR - JobManager: child process returned: 1 (Operation not permitted)
Feb 12, 2018 18:58:00.407 [0x7fadb0fff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 28160 is 1
Feb 12, 2018 18:58:01.070 [0x7fad9a7ff700] DEBUG - HTTP 200 response from GET https://plex.tv/servers//access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Feb 12, 2018 18:58:01.071 [0x7fad9a7ff700] DEBUG - MyPlex: updating with 18 access tokens
Feb 12, 2018 18:58:30.300 [0x7fad90bff700] DEBUG - Using default transcode duration of 120 minutes
Feb 12, 2018 18:58:30.300 [0x7fad90bff700] DEBUG - Started session successfully: 8c4ec87b-027f-4450-be46-99bd10d44048
Feb 12, 2018 18:58:30.300 [0x7fad90bff700] DEBUG - DVR:Recorder: It took 30.0 sec to start the session for http://192.168.10.2:5004/auto/v13.1
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] ERROR - DVR:Recorder: No part because session isn’t reporting one.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] ERROR - DVR:Recorder: Couldn’t obtain a part, something went wrong.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] ERROR - DVR:Recorder: Error 12 (There was a transcoder error) starting the record, shutting things down.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - MediaRecorderVirtual: setting stop time to 1518483510
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - DVR:Recorder: Asked to stop recording ‘2018 Winter Olympics - Alpine Skiing, Snowboarding, Speed Skating’.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - DVR:Recorder: Stopping transcode session.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - Killing job.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - Signalling job ID 28160 with 9
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - Job was already killed, not killing again.
Feb 12, 2018 18:58:30.301 [0x7fad90bff700] DEBUG - Stopping transcode session 8c4ec87b-027f-4450-be46-99bd10d44048
Feb 12, 2018 18:58:30.302 [0x7fada87ff700] DEBUG - Thread: Running async task started by thread 0x7fad90bff700.
Feb 12, 2018 18:58:30.302 [0x7fadb0fff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 28160 is 1
Feb 12, 2018 18:58:30.302 [0x7fadb0fff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 28160 is 1
Feb 12, 2018 18:58:30.303 [0x7fad90bff700] DEBUG - DVR:Grabber: Freed a tuner (now 3 available)
Feb 12, 2018 18:58:30.303 [0x7fad90bff700] DEBUG - DVR:Grabber: Operation for 2018 Winter Olympics - Alpine Skiing, Snowboarding, Speed Skating completed with status error (There was a transcoder error)
Feb 12, 2018 18:58:30.303 [0x7fada87ff700] DEBUG - Cleaning directory for session 8c4ec87b-027f-4450-be46-99bd10d44048 (/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-8c4ec87b-027f-4450-be46-99bd10d44048)
Feb 12, 2018 18:58:30.304 [0x7fad90bff700] DEBUG - Activity: Ended activity 77d97dc4-247f-4d19-a885-96cfd3313f64.
Feb 12, 2018 18:58:30.304 [0x7fad90bff700] ERROR - DVR:Grabber: Starting media grab failed.
Feb 12, 2018 18:58:30.309 [0x7fadb8bfe700] DEBUG - Auth: authenticated user 1 as mouseskowitz
Feb 12, 2018 18:58:30.309 [0x7fadb23ff700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Feb 12, 2018 18:58:30.310 [0x7fadb23ff700] DEBUG - Request: [192.168.10.7:31173 (Subnet)] GET /status/sessions/background (4 live) TLS GZIP Signed-in Token ()
Feb 12, 2018 18:58:30.311 [0x7fadb37ff700] DEBUG - Thread: Running async task started by thread 0x7fadb93ff700.
Feb 12, 2018 18:58:30.311 [0x7fadb93ff700] DEBUG - Completed: [192.168.10.7:31173] 200 GET /status/sessions/background (4 live) TLS GZIP 1ms 397 bytes (pipelined: 1)
Feb 12, 2018 18:58:30.346 [0x7fadb8bfe700] DEBUG - Auth: authenticated user 1 as *
Feb 12, 2018 18:58:30.346 [0x7fadb23ff700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Feb 12, 2018 18:58:30.346 [0x7fadb23ff700] DEBUG - Request: [192.168.10.7:31173 (Subnet)] GET /status/sessions/background (4 live) TLS GZIP Signed-in Token ()
Feb 12, 2018 18:58:30.347 [0x7fad8a7fe700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Feb 12, 2018 18:58:30.347 [0x7fadb8bfe700] DEBUG - Completed: [192.168.10.7:31173] 200 GET /status/sessions/background (4 live) TLS GZIP 1ms 397 bytes (pipelined: 2)
Feb 12, 2018 18:58:30.349 [0x7fadb8bfe700] DEBUG - Auth: authenticated user 1 as *
Feb 12, 2018 18:58:30.349 [0x7fad983ff700] DEBUG - Thread: Running async task started by thread 0x7fadb8bfe700.
Feb 12, 2018 18:58:30.349 [0x7fadb93ff700] DEBUG - Auth: authenticated user 1 as *
Feb 12, 2018 18:58:30.349 [0x7fad983ff700] DEBUG - Request: [192.168.10.7:31174 (Subnet)] GET /media/subscriptions/scheduled (6 live) TLS GZIP Signed-in Token ()
Feb 12, 2018 18:58:30.351 [0x7fada5bff700] DEBUG - Thread: Running async task started by thread 0x7fadb93ff700.
Feb 12, 2018 18:58:30.351 [0x7fada5bff700] DEBUG - Request: [192.168.10.7:31173 (Subnet)] GET /media/subscriptions (6 live) TLS GZIP Signed-in Token (*)
Feb 12, 2018 18:58:30.355 [0x7fadb4fff700] DEBUG - Thread: Running async task started by thread 0x7fadb93ff700.
Feb 12, 2018 18:58:30.355 [0x7fadb93ff700] DEBUG - Completed: [192.168.10.7:31173] 200 GET /media/subscriptions (6 live) TLS GZIP 5ms 656 bytes (pipelined: 3)
Feb 12, 2018 18:58:30.356 [0x7fad9a7ff700] DEBUG - Thread: Running async task started by thread 0x7fadb93ff700.
Feb 12, 2018 18:58:30.357 [0x7fadb93ff700] DEBUG - Completed: [192.168.10.7:31174] 200 GET /media/subscriptions/scheduled (6 live) TLS GZIP 7ms 7278 bytes (pipelined: 1)
Feb 12, 2018 18:58:31.287 [0x7fad9ffff700] DEBUG - DVR:Recorder: Asked to stop recording ‘2018 Winter Olympics - Alpine Skiing, Snowboarding, Speed Skating’.
Today it appears to be working. Not really sure what changed. We’ll have to see how reliable it is.
