Plex seems to malfunction and nothing records

General Discussions Plex Features
41

Network is rock solid with an HP Procurve GB switch. I have fixed the IPs of my 2 tuners at 172.16.10.25 and 172.16.10.26. I use these tuners with the Channels app to watch TV on my Apple TV and they work flawlessly.

These aborted tasks I believe are the ones that are killed when I stop/start the Plex Media Server.

I’ll check out the firmware of the devices. It was upgraded just recently when I purchased the Apple TVs, I believe. They were recording perfectly with Windows Media Center, and actually had been working great with Plex until later version of the beta came around. Now I can’t get them to work reliably at all. I just restarted the media server to make certain to get a show for tonight, and that one is currently sitting at 0 bytes and is not recording at all (Supergirl S02E14 Homecoming). I haven’t stopped/started because other recordings are going right now just fine.

42

Firmware is a few months out of date. I’ll update when it’s done with these recordings.

FYI The firmware is available by going to:
http://my.hdhomerun.com

43

However–one thing that tells me this is a bigger issue than a firmware is the fact that the shows that are hung at 0-bytes have disappeared from the Recording Schedule Calendar View. Supergirl was in this list before the recording started. Now it is gone.

You pulled a log that said “Deadlocked”–SQL deadlock might explain that.

44

Question for other HDHomeRun Prime users. How do you have your BDA Compatibility Mode set? I used to record with Windows Media Center, so mine is set to that.

45

I am set to Default.

I do not use Media center as it is not really available for windows 10.

46

@gadgetgeek2000
actually that’s an episode name, I don’t recall ever discovering it, nor mentioning it. I mentioned filelocks in another thread when the user chose his words poorly and was deceptively undescriptive.

MediaSub: Episode ‘Deadlock’ airs on channel 99 at 2017-03-04 05:00:00

reboot the box, I think the firmware issue might resolve some of your issues. I’m still seeing 504 errors from the tuner with the IP 172.16.10.25 from the last set of log’s you shared.

If the issue persists, dump more logs on ‘us’

47

Actions taken last night:

  1. Stop the Plex Media Server
  2. Updated the software in Windows and firmware on both HDHomeRun Prime devices. http://my.hdhomerun.com
  3. Performed a channel scan for each unit from the device configuration utility.
  4. Restarted Plex Media Server
  5. Made a list of duplicate channels (SD and HD, Attached) and
  6. Deactivated the SD channels for each pair in Plex. Also deactivated any stations that I don’t use/record.

Plex is running now. Will wait to see if I find any more malfunctions. Logs attached as of this morning after several recordings completed. Restart performed last night.

48

@Gloppie_ said:
@gadgetgeek2000
actually that’s an episode name, I don’t recall ever discovering it, nor mentioning it. I mentioned filelocks in another thread when the user chose his words poorly and was deceptively undescriptive.

MediaSub: Episode ‘Deadlock’ airs on channel 99 at 2017-03-04 05:00:00

reboot the box, I think the firmware issue might resolve some of your issues. I’m still seeing 504 errors from the tuner with the IP 172.16.10.25 from the last set of log’s you shared.

If the issue persists, dump more logs on ‘us’

Funny, I read deadlock as in “plex resolved the deadlock by stopping the recording”. :slight_smile:

49

I’ve got 2 grab .TS files that are zero-byte and not recording right now.

b8timget4g3h.png1157×308 36.6 KB

It looks like with all the adjustments made so far that we haven’t affected change yet.

50

:frowning:

Both tuners think they are recording something right now.,

Which file are you looking at in the logs to find the DVR errors? I’d love to understand the logs to search.

51

@gadgetgeek2000 said:
Here are the logs if anyone can look.

The screenshots showing the last modified date/time for the zero length files were very helpful. It appears to be related to getting a 503 response from the tuner.

Could you tell me if all the zero length files relate to back-to-back recordings? i.e. ones that start immediately after one that was scheduled before -

52

I’m not sure what a 503 response is. There are 6 tuners in the system so you should be able to find a tuner to record on. As I mentioned earlier, we also use the Channels app on AppleTV to watch live TV from the HD Homerun Prime units as well. I’m guessing you can never be sure that a tuner will be available.

I have my system set to record 2 minutes before the start time and go 2 minutes after as well.

Here is a screenshot of my recording schedule. The shows like The Big Bang Theory are recording episodes all the time.

53

The log showed that the tuner on 172.16.10.25 on channel 704 was still recording the tail end of a recording when a new one was requested at 19:28 and that was when the 503 rejection (Http Error Service Unavailable). The earlier recording finished at 19:32. So my guess is that the overlap is leading to the zero length files - I am discussing this with the development team but thought I should share my thoughts on this with you

54

From the development guide:
silicondust.com/hdhomerun/hdhomerun_http_development.pdf

Errors:

  • If the virtual channel number is not known the tuner will return “404 Not Found”.
  • If the request cannot be completed at this time (for example all tuners are in use) the tuner will return “503 Service Unavailable”.
  • If the program cannot be not found in the stream within 5 seconds or the program cannot be authorized within 5 seconds the tuner will return “503 Service Unavailable”.
  • If the program requires content-protection not requested by the client the tuner will return “503 Service Unavailable” after 5 seconds. This error code may change in the future to return a more relevant error code

Interesting.

55

I’m not sure why the devices would return a 503. Last night, for example, there was only one show being recorded (The Librarians), and everyone was in bed so all other tuners were idle.

it13zcpypjla.png945×96 4.41 KB

56

@gadgetgeek2000 said:
I’m not sure why the devices would return a 503. Last night, for example, there was only one show being recorded (The Librarians), and everyone was in bed so all other tuners were idle.

945×96 4.41 KB

Will have a look at the new logs later today.

@gadgetgeek2000 said:
From the development guide:
silicondust.com/hdhomerun/hdhomerun_http_development.pdf

Errors:

  • If the virtual channel number is not known the tuner will return “404 Not Found”.
  • If the request cannot be completed at this time (for example all tuners are in use) the tuner will return “503 Service Unavailable”.
  • If the program cannot be not found in the stream within 5 seconds or the program cannot be authorized within 5 seconds the tuner will return “503 Service Unavailable”.
  • If the program requires content-protection not requested by the client the tuner will return “503 Service Unavailable” after 5 seconds. This error code may change in the future to return a more relevant error code

Interesting.

There was a 5 second delay before the 503 was returned. We have one starting at 18:58:00 which would finish at 19:32

Feb 25, 2017 18:58:00.813 [7144] DEBUG - HTTP requesting GET http://172.16.10.25:5004/auto/v704?duration=2040

Then for 19:30 The Big Bang Theory S01E11 (The Pancake Batter Anomaly) - requested 2 minutes early at 19:28

Feb 25, 2017 19:28:00.823 [8256] DEBUG - HTTP requesting GET http://172.16.10.25:5004/auto/v704?duration=2040

Feb 25, 2017 19:28:05.902 [8256] DEBUG - HTTP 503 response from GET http://172.16.10.25:5004/auto/v704?duration=2040
57

@sa2000 Can you check to see if the Dev team is allocating the tuner at the time of scheduling? This is what it seems like from a quick view of some people’s logs.

Obviously if this is how it currently works it’s always going to have problems. No DVR should ever hard code the tuner it should use because you never know if it’s going to be available (another system or Live TV could be using it). The tuner could have been removed or a new tuner could have been added.

Scheduling should check the known number or tuners for conflict resolution without worry or need of specific tuner.

So anyway, can you check on this?

58

Yes
I have brought up this issue that Plex was not looking at tuner availability to be sure no other user was using a tuner to just watch TV using another app.
I posted this issue when it was observed some time ago that in the DVR settings page it would display tuners available when they were in use by another process.

It does look like this user does in fact use his HDHR as a TV viewing device as just a player not thru DVR only.

59

@gadgetgeek2000 said:
I’m not sure why the devices would return a 503. Last night, for example, there was only one show being recorded (The Librarians), and everyone was in bed so all other tuners were idle.

945×96 4.41 KB

Checking the 01:58 am file And The City of Light - we had overlap. An earlier 64 minute recording started at 00:58am

Mar 01, 2017 00:58:00.087 [7460] DEBUG - HDHomerun Grabber: Starting a media grab on device device://tv.plex.grabbers.hdhomerun/131949C0 tuner 0.
Mar 01, 2017 00:58:00.087 [7460] DEBUG - MediaGrabber: Starting operation for 'E8 - And the Heart of Darkness'
Mar 01, 2017 00:58:00.087 [7460] DEBUG - Activity: registered new activity a7a82550-7080-4356-825c-7167ac381dbc - Recording

Mar 01, 2017 00:58:00.087 [8012] INFO - Notification: Recording E8 - And the Heart of Darkness - 
Mar 01, 2017 00:58:00.087 [9708] DEBUG - MediaSub: Failed to resolve subscription for 'guid: com.gracenote.onconnect://show/10783325 thumb: http://tmsimg.plex.tv/assets/p13140326_b_v5_aa.jpg title: The Librarians type: 2 year: 2014' to library item
Mar 01, 2017 00:58:00.087 [9708] DEBUG - Media Grabber: Saving recording to D:\Plex Recorded TV\.grab\b0d3950d00a0fc228fd3333d6b696ace2a3a46e0
Mar 01, 2017 00:58:00.087 [9708] DEBUG - HDHR Grabber: Going to record for 3840 seconds, final URL is http://172.16.10.25:5004/auto/v737?duration=3840
Mar 01, 2017 00:58:00.087 [9708] DEBUG - MediaGrabber: Waiting for a tuner (2 available).
Mar 01, 2017 00:58:00.087 [9708] DEBUG - MediaGrabber: Allocated a tuner (1 left)
Mar 01, 2017 00:58:00.087 [9708] DEBUG - HTTP requesting GET http://172.16.10.25:5004/auto/v737?duration=3840

and then the one that failed 503

Mar 01, 2017 01:58:00.088 [4388] DEBUG - HDHomerun Grabber: Starting a media grab on device device://tv.plex.grabbers.hdhomerun/131949C0 tuner 1.
Mar 01, 2017 01:58:00.088 [4388] DEBUG - MediaGrabber: Starting operation for 'E9 - And the City of Light'
Mar 01, 2017 01:58:00.088 [4388] DEBUG - Activity: registered new activity a44b1c84-31bf-44dc-afc9-3e48ac6f0b7d - Recording
Mar 01, 2017 01:58:00.088 [5364] INFO - Notification: Recording E9 - And the City of Light - 
Mar 01, 2017 01:58:00.088 [10216] DEBUG - MediaSub: Failed to resolve subscription for 'guid: com.gracenote.onconnect://show/10783325 thumb: http://tmsimg.plex.tv/assets/p13140326_b_v5_aa.jpg title: The Librarians type: 2 year: 2014' to library item

Mar 01, 2017 01:58:00.088 [10216] DEBUG - Media Grabber: Saving recording to D:\Plex Recorded TV\.grab\a6fd6e2adfbc31d92fd3b3b133fb0ca78b500360
Mar 01, 2017 01:58:00.088 [10216] DEBUG - HDHR Grabber: Going to record for 3840 seconds, final URL is http://172.16.10.25:5004/auto/v737?duration=3840
Mar 01, 2017 01:58:00.088 [10216] DEBUG - MediaGrabber: Waiting for a tuner (1 available).
Mar 01, 2017 01:58:00.088 [10216] DEBUG - MediaGrabber: Allocated a tuner (0 left)
Mar 01, 2017 01:58:00.088 [10216] DEBUG - HTTP requesting GET http://172.16.10.25:5004/auto/v737?duration=3840
Mar 01, 2017 01:58:05.174 [10216] DEBUG - HTTP 503 response from GET http://172.16.10.25:5004/auto/v737?duration=3840

This is actually implying that it did use a different tuner for the two recording

Mar 01, 2017 00:58:00.087 [9708] DEBUG - MediaGrabber: Waiting for a tuner (2 available).
Mar 01, 2017 00:58:00.087 [9708] DEBUG - MediaGrabber: Allocated a tuner (1 left)
Mar 01, 2017 00:58:00.087 [9708] DEBUG - HTTP requesting GET http://172.16.10.25:5004/auto/v737?duration=3840
. . .
Mar 01, 2017 01:58:00.088 [10216] DEBUG - MediaGrabber: Waiting for a tuner (1 available).
Mar 01, 2017 01:58:00.088 [10216] DEBUG - MediaGrabber: Allocated a tuner (0 left)
Mar 01, 2017 01:58:00.088 [10216] DEBUG - HTTP requesting GET http://172.16.10.25:5004/auto/v737?duration=3840
Mar 01, 2017 01:58:05.174 [10216] DEBUG - HTTP 503 response from GET http://172.16.10.25:5004/auto/v737?duration=3840

I need to discuss this with the development team

@cayars said:
@sa2000 Can you check to see if the Dev team is allocating the tuner at the time of scheduling? This is what it seems like from a quick view of some people’s logs.

Obviously if this is how it currently works it’s always going to have problems. No DVR should ever hard code the tuner it should use because you never know if it’s going to be available (another system or Live TV could be using it). The tuner could have been removed or a new tuner could have been added.

Scheduling should check the known number or tuners for conflict resolution without worry or need of specific tuner.

So anyway, can you check on this?

The log suggests it is allocating a tuner. I will discuss this with the development team

60

@gadgetgeek2000 said:
I’m not sure why the devices would return a 503. Last night, for example, there was only one show being recorded (The Librarians), and everyone was in bed so all other tuners were idle.

945×96 4.41 KB

The 05:58am one was still active when the logs were captured

Mar 01, 2017 06:48:02.203 [6492] DEBUG - Activity: updated activity d3ab0eaa-25ff-419a-a55b-6a9781fac3d5 - completed 80% - Recording

so not sure exactly what time that screenshot was taken but may be the file size / date time are not being updated till the end