I’m running 1.11.3. 4793 on Ubuntu 16.04, just upgraded to .4803 before posting. When trying to record the Olympics the recordings end up ~16 minutes short. I have it set to start 2 minutes before and go 2 minutes after. I’m pretty sure the time is missing from the beginning on the recording. I’m pulling from a HDHomerun Connect with 2 tuners. I also have a Windows Media Center box recording since I can’t trust Plex yet.
Is it possible that the recording isn’t starting because the tuner that Plex wants to use is already in use, i.e. 0 vs 1? If this is the case is there a way to have it not wait 15 minutes to start recording? Or could there be another bug in the system? I can’t go far enough back in the logs at this point to see what’s going on.
The one thing that has recorded today was the correct length. So maybe the fix was in .4803. Time will tell.
FYI. Plex does not specify a specific tuner on a device to be used. It will as part of it’s scheduling logic show in the logs something like Device 0 Tuner 0. But to a HDHR device there is no specification of a specific tuner to use, just the device it is requesting access to a channel from. For instance: http://192.168.3.119:5004/auto/v780, using device 192.168.3.119 tune to channel 780. No specific tuner on the device is requested.
If you were missing minutes off the front of a recording my guess is that you had both tuners in use on your HDHR Connect device. When a tuner was freed Plex started the recording after it’s scheduled start time because you have the Allow Partial Recordings option selected.
I had thought about the recording conflict thing as well, but I can’t find one. Olympics has been the only thing on the past several days, and they’re not back to back.
The Plex Media Server logs would have information on why the recording did not start at the scheduled time.
The logs go back less than 3 hours, and the one recording in the time frame was the one that went as scheduled today. Any way to change the logging so I can actually see what’s going on?
You can use the Plex Advanced, Hidden Server Settings to increase the number of log files kept. The default is 5 which keeps 5 previous versions and the current log file. Look for the LogNumFiles option in the table at the bottom of the page. I would recommend a restart of the computer after adding the option to ensure Plex is running with the new preference.
Thanks. Bumped LogNumFiles up to 10. Hopefully I’ll be able to get more like 5 hours and be able to see what’s going on here.
That didn’t really work, I only got one more log file for the server logs. Is there a max size setting somewhere as well. I thought I saw one at one point, but I can’t find it now?
You sure it is not just adding additional logs as the current one fills up? Maybe later you will have 8 log files. With all the testing I do mine is set at 100 to ensure I get logs for several days. As long as you have it set correctly which it sounds like you do since you have the additional log file.
You’re correct. I think I was getting confused with the which line was which on the time stamps. There are other logs that are up to 10 old versions. Now if I can just catch the errors. I did have another transcoder error tonight. I think this one is due to the Media Center box using all the tuners.
I finally have some log info. Does this make sense to anyone?
Log entry when recording was supposed to start.
Feb 21, 2018 13:58:00.960 [0x7fcd54bff700] DEBUG - DVR:Grabber: Starting operation for ‘2018 Winter Olympics - Speed Skating, Men’s Cross-Country Skiing’.
Feb 21, 2018 13:58:00.961 [0x7fcd54bff700] DEBUG - Activity: registered new activity be7cf00c-0a86-48d7-bb91-4cd07b74fe90 - Recording
Feb 21, 2018 13:58:00.961 [0x7fcd54bff700] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10412402 (Silicondust HDHomeRun CONNECT, supported) tuner 0.
Feb 21, 2018 13:58:00.961 [0x7fcd437ff700] DEBUG - Thread: Running async task started by thread 0x7fcd54bff700.
Feb 21, 2018 13:58:00.963 [0x7fcd54bff700] DEBUG - DVR:Subscription: Resolved subscription to library item ‘2018 Winter Olympics’ (10127)
Feb 21, 2018 13:58:00.966 [0x7fcd54bff700] DEBUG - There were 1 top-level paths for 2018 Winter Olympics.
Notifications like this every 1% up to this point.
Feb 21, 2018 14:12:55.043 [0x7fcd437ff700] DEBUG - Activity: updated activity be7cf00c-0a86-48d7-bb91-4cd07b74fe90 - completed 12% - Recording
Then the recording actually started here.
Feb 21, 2018 14:13:32.440 [0x7fcd54bff700] DEBUG - DVR:Grabber: Saving recording to “/home/phil/media/tv/.grab/26d983040bc0ee670b20b3c0933a75bf0f17e11c”
Feb 21, 2018 14:13:32.501 [0x7fcd54bff700] DEBUG - HTTP requesting GET http://192.168.10.2:80/lineup.json
Feb 21, 2018 14:13:32.516 [0x7fcd54bff700] DEBUG - HTTP 200 response from GET http://192.168.10.2:80/lineup.json
Feb 21, 2018 14:13:32.516 [0x7fcd54bff700] DEBUG - DVR:Grabber: Going to record for 6508 seconds, final URL is http://192.168.10.2:5004/auto/v13.1
Feb 21, 2018 14:13:32.517 [0x7fcd54bff700] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘2018 Winter Olympics - Speed Skating, Men’s Cross-Country Skiing’ in 6508 seconds.
Feb 21, 2018 14:13:32.517 [0x7fcd54bff700] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.10.2:5004/auto/v13.1.
Feb 21, 2018 14:13:32.519 [0x7fcd54bff700] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Feb 21, 2018 14:13:32.520 [0x7fcd54bff700] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
Feb 21, 2018 14:13:32.521 [0x7fcd54bff700] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Feb 21, 2018 14:13:32.521 [0x7fcd54bff700] DEBUG - Selecting best audio stream for part ID -1 (autoselect: 0 language: en)
Feb 21, 2018 14:13:32.521 [0x7fcd54bff700] DEBUG - Audio Stream: -1, Subtitle Stream: -1
Feb 21, 2018 14:13:32.522 [0x7fcd54bff700] DEBUG - MDE: Selected protocol hls; container: mpegts
Feb 21, 2018 14:13:32.522 [0x7fcd54bff700] ERROR - Unable to find title for item of type 5
Feb 21, 2018 14:13:32.522 [0x7fcd54bff700] DEBUG - MDE: analyzing media item -1
Feb 21, 2018 14:13:32.522 [0x7fcd54bff700] DEBUG - MDE: : no direct play video profile exists for http/mpegts/
Feb 21, 2018 14:13:32.522 [0x7fcd54bff700] DEBUG - MDE: : no direct play video profile exists for http/mpegts//
Feb 21, 2018 14:13:32.523 [0x7fcd54bff700] DEBUG - MDE: : codec is unavailable for analysis
Feb 21, 2018 14:13:32.523 [0x7fcd54bff700] DEBUG - MDE: : codec is unavailable for analysis
Feb 21, 2018 14:13:32.523 [0x7fcd54bff700] ERROR - Unable to find title for item of type 5
Feb 21, 2018 14:13:32.523 [0x7fcd54bff700] DEBUG - MDE: : selected media 0 / -1
Then it stopped at the correct time.
Feb 21, 2018 16:02:00.522 [0x7fcd377ff700] DEBUG - DVR:Grabber: Cancelling operation for ‘2018 Winter Olympics - Speed Skating, Men’s Cross-Country Skiing’ with status complete.
Feb 21, 2018 16:02:00.523 [0x7fcd377ff700] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Feb 21, 2018 16:02:00.523 [0x7fcd377ff700] DEBUG - MediaRecorderVirtual: setting stop time to 1519250520
Do you have the full logs you can post?
Here’s a link to a drop box share. There are 5 log files that cover the time period of the recording. https://www.dropbox.com/sh/2y95210dh05yjfo/AADHoSSwHJGl6oUberi2JSrYa?dl=0
@johnm_ColaSC said:
Do you have the full logs you can post?
Were you able to find anything in the logs?
Sorry have been really busy with my job the last few days and will be for a couple of weeks. I looked back through them again today to refamiliarize myself with the issue. I don’t see anything other than what you reported. I sent a message on the Plex Internal message system and only got one response that they had no idea either. Really odd to see recording appear to start but then grab folder is not created or tuner assigned for 15 minutes.
Thanks for looking. Do I need to submit a bug report or anything like that? This has happened at least 6 or 8 times, but it doesn’t always.
I never figured out what was actually causing the problem, but it is something related to the first VM I used. I installed the Plex Media Server on a fresh CentOS 7 VM and everything seems to be working correctly now. I don’t know if the original problem is Ubuntu 16.04 related or something I messed up somewhere in the config.
