Recordings stopped before show ending

Live TV & DVR
,
1

I’ve been having issues lately where recordings won’t be complete. Like it will record for sometime and just stop. It’s not comskip, as I have MCEBuddy doing that work, plus I have an archive of the full recording. I was afraid I was going to have issues recording Marvel’s Agents finale and I did. It recorded 41min of a 2 hour show (so ending around 8:41p). I think I’ve caught it in the logs, but I’d like to know what’s happening. This has happened on other stations, almost at least once daily.

I’ve had other issues where it just didn’t record this specific show’s new episode, even though it was on the schedule. Like it was on the schedule, next day it shows nothing, with no error message. Unfortunately, I don’t have any logs to show.

Server Version#: 1.19.5.3112
Player Version#:
Tuner Make/Model: HDHomeRun EXTEND
Guide/Lineup name: Broadcast TV Milwaukee/Surround OTA Broadcast
Using XMLTV?: No
Channel number/Name: 12.1

Plex Media Server Logs_2020-08-12_21-07-26.zip (6.6 MB)

2

The full logs would have been nice. You can get these by going to Settings/Troubleshooting and clicking the Download Logs link.

What is the M: Drive? How is it formatted?

3

Sorry about that. I’ve updated the post with all the logs.

M drive is my media drive. A DAS Drobo 3, formated NTFS.

4

I’ll try to look over the full logs later tonight. The 41 minute mark was interesting to me when you mentioned it because that is about the time it would take a recording to get to 4GB which is the max size of a file for a FAT32 formatted disk.

5

Thanks, it’s appreciated.

It has recorded the full hour of this show usually. This the first time this show has been cut, but I’ve had others only record 5 or 10 minutes, on different networks. But at least twice this season it was supposed to record and then didn’t. But that’s an issue we won’t find here.

6

Can you download the logs from the HDHR tuner and post. Curious to see what they show.

http://192.168.1.30/log.html

About all I am seeing in the Plex logs at failure is:

Aug 12, 2020 20:41:31.369 [1112] ERROR - [Transcoder] [tcp @ 0278ca80] Connection to tcp://127.0.0.1:32400 failed: Error number -138 occurred
Aug 12, 2020 20:41:31.370 [1112] ERROR - [Transcoder] [stream_segment,ssegment @ 0426ad40] Failed to open segment list 'http://127.0.0.1:32400/video/:/transcode/session/69fdcfe9-48a7-49f3-b5a3-888d174b2c13/0f665872-5b85-418a-97d4-ed01b367e0ec/seglist?X-Plex-Http-Pipeline=infinite'
Aug 12, 2020 20:41:31.385 [1112] DEBUG - Transcoder segment range: 0 - 2479 (2479)
Aug 12, 2020 20:41:31.385 [20624] ERROR - [Transcoder] Error writing trailer of media-%05d.ts: Error number -138 occurred
Aug 12, 2020 20:41:31.396 [12968] DEBUG - Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\Plex Transcoder.exe' exit code for process 18016 is 1 (failure)
Aug 12, 2020 20:41:31.396 [20312] DEBUG - Grabber: Freed a tuner on device://tv.plex.grabbers.hdhomerun/10568838 (now 2 available)
7

I’ll attach the whole thing, but I think this is the only relevant part. Date/time is off though. And I see a firmware update is needed.

20200813-01:00:00 Tuner: tuner0 tuning 12.1 WISN TV (8vsb:557MHz-3)
20200813-01:00:00 Tuner: tuner0 streaming http to 192.168.1.13:57203
20200813-01:41:32 Tuner: tuner0 http stream ended (remote closed)
20200813-01:41:53 Tuner: tuner0 tuning 12.1 WISN TV (8vsb:557MHz-3)
20200813-01:41:54 Tuner: tuner0 streaming http to 192.168.1.13:51235
20200813-01:42:02 Tuner: tuner0 http stream ended (remote closed)

HDHR log.txt (60.2 KB)

8

@johnm_ColaSC Did you find anything unusual?

I’m having this happen more and more, usually 1-2 recording per day. Unfortunately I don’t have any logs to show since I don’t catch it until the next day. I’ll try to grab the logs closer to when it happened. Lately the cut short recordings have been less than 1 min.

9

The only thing I noticed in the logs was what was previously mentioned.

Aug 12, 2020 20:41:31.369 [1112] ERROR - [Transcoder] [tcp @ 0278ca80] Connection to tcp://127.0.0.1:32400 failed: Error number -138 occurred
Aug 12, 2020 20:41:31.370 [1112] ERROR - [Transcoder] [stream_segment,ssegment @ 0426ad40] Failed to open segment list 'http://127.0.0.1:32400/video/:/transcode/session/69fdcfe9-48a7-49f3-b5a3-888d174b2c13/0f665872-5b85-418a-97d4-ed01b367e0ec/seglist?X-Plex-Http-Pipeline=infinite'
Aug 12, 2020 20:41:31.385 [1112] DEBUG - Transcoder segment range: 0 - 2479 (2479)
Aug 12, 2020 20:41:31.385 [20624] ERROR - [Transcoder] Error writing trailer of media-%05d.ts: Error number -138 occurred
Aug 12, 2020 20:41:31.396 [12968] DEBUG - Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\Plex Transcoder.exe' exit code for process 18016 is 1 (failure)
Aug 12, 2020 20:41:31.396 [20312] DEBUG - Grabber: Freed a tuner on device://tv.plex.grabbers.hdhomerun/10568838 (now 2 available)

It seems to match up with the HDHR logs showing the remote closed connection. Why Plex transcoder aborted I am not sure. There isn’t much else in the logs that I am seeing.

Have you tried recording to the C drive instead of to the Drobo drive? Curious if that would yield better results possibly.

10

I’ll add these logs, just in case they reveal something more. All of my recordings for the last 2 days have stopped recording after 1 min.

I think it’s more of a transcoder issue. Even watching live TV is a struggle, and I received the following error message in the console after the tuner quit after about 1 min. I don’t have issues watching through the HDHR app in Windows. I did restart (un/replug) the HDHR, but that appears to have done nothing.

[Transcoder] [tcp @ 0429ff00] Connection to tcp://127.0.0.1:32400 failed: Error number -138 occurred

Maybe I need to reinstall PMS? I need to remember how to maintain the data though.

Plex Media Server Logs_2020-09-01_18-50-48.zip (5.7 MB)

11

Do you have a time when a recording should have started? I am not finding anything in the logs with normal searches I use to find recordings. I am also extremely busy with my day job now so replies could be delayed.

12

9/1, 4:00p, 4:30p, and 5:00p

I thought I grabbed the logs close enough to the error.

No worries, I’m in no hurry. I appreciate the help.

13

Just looked at logs again. The oldest log: Plex.Media.Server.5.log goes back to 18:25:45. The 6 log files for Plex Media Server only cover 25 minutes. Everywhere I look in the logs it appears Plex is doing stuff with photos. There was a lot of activity with photos in the last set of logs as well. Might want to use the Advanced, Hidden Server Settings to increase the LogNumFiles setting higher than the default 5 in order to capture more log entries to see DVR issues.

14

I did notice that it’s always scanning photos. Which is odd, since I haven’t added a photo in months, since Camera Upload has been broken for me.

I canceled all my current DVR shows, but I’ll give it a go and just test the Plex Tuner over live TV as it seems that’s the same issue.

15

Hopefully there’s something here to indicate what’s happening with the tuner. Attempted to record something around 4:30p. There also should be failed live tv after 4p, sorry I don’t have an exact time.

Plex Media Server Logs_2020-09-10_16-36-03.zip (14.8 MB)

16

Transcoder Dev is saying the error showing error number -138 is a windows error for a timeout on the request. We discussed getting a set of verbose logs to see if there is any additional information. Before we try that it would be nice to eliminate all the messages coming from the scanning of your photos. If you’re not using photos could you possibly remove the library from Plex that way it stops the scanning or rename the top-level folder on your drive the photos are stored in so Plex quits trying to scan them all the time?

The other thing I have noticed in the logs is numerous slow query messages, these were just the 16:33 messages:

Sep 10, 2020 16:33:00.325 [16904] WARN - SLOW QUERY: It took 203.125000 ms to retrieve 16 items.
Sep 10, 2020 16:33:00.346 [10556] WARN - SLOW QUERY: It took 375.000000 ms to retrieve 50 items.
Sep 10, 2020 16:33:05.309 [16036] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 10 items.
Sep 10, 2020 16:33:05.319 [10556] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 16 items.
Sep 10, 2020 16:33:05.329 [4220] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 31 items.
Sep 10, 2020 16:33:05.330 [4604] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 31 items.
Sep 10, 2020 16:33:05.362 [16904] WARN - SLOW QUERY: It took 234.375000 ms to retrieve 31 items.
Sep 10, 2020 16:33:05.368 [7912] WARN - SLOW QUERY: It took 234.375000 ms to retrieve 50 items.
Sep 10, 2020 16:33:05.397 [4516] WARN - SLOW QUERY: It took 203.125000 ms to retrieve 50 items.
Sep 10, 2020 16:33:10.282 [4516] WARN - SLOW QUERY: It took 218.750000 ms to retrieve 16 items.
Sep 10, 2020 16:33:10.312 [18320] WARN - SLOW QUERY: It took 312.500000 ms to retrieve 16 items.
Sep 10, 2020 16:33:10.341 [7912] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 31 items.
Sep 10, 2020 16:33:10.374 [10556] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 31 items.
Sep 10, 2020 16:33:10.375 [4604] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 31 items.
Sep 10, 2020 16:33:10.387 [16036] WARN - SLOW QUERY: It took 375.000000 ms to retrieve 50 items.
Sep 10, 2020 16:33:15.326 [16916] WARN - SLOW QUERY: It took 234.375000 ms to retrieve 16 items.
Sep 10, 2020 16:33:15.397 [16036] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 50 items.
Sep 10, 2020 16:33:20.295 [13540] WARN - SLOW QUERY: It took 203.125000 ms to retrieve 16 items.
Sep 10, 2020 16:33:20.341 [16916] WARN - SLOW QUERY: It took 312.500000 ms to retrieve 10 items.
Sep 10, 2020 16:33:20.357 [16036] WARN - SLOW QUERY: It took 468.750000 ms to retrieve 16 items.
Sep 10, 2020 16:33:20.360 [4516] WARN - SLOW QUERY: It took 296.875000 ms to retrieve 31 items.
Sep 10, 2020 16:33:20.362 [7912] WARN - SLOW QUERY: It took 296.875000 ms to retrieve 31 items.
Sep 10, 2020 16:33:20.397 [18320] WARN - SLOW QUERY: It took 406.250000 ms to retrieve 50 items.
Sep 10, 2020 16:33:25.309 [4220] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 16 items.
Sep 10, 2020 16:33:25.328 [13540] WARN - SLOW QUERY: It took 281.250000 ms to retrieve 16 items.
Sep 10, 2020 16:33:25.899 [18296] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 16 items.
Sep 10, 2020 16:33:25.935 [4604] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 31 items.
Sep 10, 2020 16:33:26.024 [7912] WARN - SLOW QUERY: It took 203.125000 ms to retrieve 50 items.
Sep 10, 2020 16:33:30.050 [18320] WARN - SLOW QUERY: It took 234.375000 ms to retrieve 50 items.
Sep 10, 2020 16:33:31.856 [5024] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 50 items.
Sep 10, 2020 16:33:42.861 [16036] WARN - SLOW QUERY: It took 203.125000 ms to retrieve 16 items.
Sep 10, 2020 16:33:54.077 [12504] WARN - SLOW QUERY: It took 312.500000 ms to retrieve 16 items.
Sep 10, 2020 16:33:54.141 [16036] WARN - SLOW QUERY: It took 406.250000 ms to retrieve 31 items.
Sep 10, 2020 16:33:54.143 [4516] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 31 items.
Sep 10, 2020 16:33:54.145 [18296] WARN - SLOW QUERY: It took 406.250000 ms to retrieve 50 items.
Sep 10, 2020 16:33:54.152 [5024] WARN - SLOW QUERY: It took 265.625000 ms to retrieve 16 items.
Sep 10, 2020 16:33:54.171 [4604] WARN - SLOW QUERY: It took 328.125000 ms to retrieve 50 items.

You can try to optimize the database by going to Settings/Troubleshooting and clicking the Optimize Database link.

If you can look at the logs after removing the photos library or changing the top-level folder so Plex is no longer scanning the photos constantly, and optimizing the database to see if you are no longer seeing slow query or photo scanning entries.

If the logs look better then we can try turning on Verbose logging. Once turned on restart Plex Media Server so the Verbose change is active. Then try recording something. If it fails grab the logs immediately after the failure. I noticed you have changed the LogNumFiles setting to 15 so hopefully, that will be enough log files to capture the failure. The Dev did say that verbose might not even indicate why Windows is giving the TimeOut error.

17

I received a message from another Employee that said this issue is more than likely one he has written about on other forum posts. The one I found that he said to search for was:

In the referenced post, he points to a Microsoft doc about the TCP settings. If you have already completed the Database Optimization which definitely should be done to try to get rid of those Slow Query messages I would suggest trying to changes he referenced in this other forum topic. The registry entry referenced on my system was already set to 30. I would suggest verifying each setting and keeping current settings before making the changes.

Plex DVR cutting off 60 min TV shows at 42 minutes
18

Good news. I completed the database optimization and then added the TcpTimedWaitDelay (30) to the registry. Since then there has been no issues recording or watching live tv.

I wasn’t sure what to do with the second part, doubling the size of the ports. I didn’t dig much into it since the registry edit did it.

NetSh INT IPV4 SET DynamicPort TCP Start=32768 num=32768
NetSh INT IPV6 SET DynamicPort TCP Start=32768 num=32768

Are those terminal/power shell commands?

Anyways, thanks for all the help!

19

Good to hear that the Database Optimization and TcpTimedWaitDelay setting fixed the issue. The NetSh command would be entered at the command prompt. But if the issue has been resolved I wouldn’t worry about them.

20

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.