Stopped recording after an hour

[jcole998]

I had a very rare recording failure this morning: Upon signing in, I noticed that the tray icon was red. Normal enough except that no Hauppauge tuners were in use, either the DCR-3250 or the HDPVR2. These are all the devices I have. The desktop app showed what was scheduled to record so I looked at the recording folders and there it was, still open. I also looked at the DCR-3250's website for tuner status and no tuners were in use even though the tray icon showed tuner 0 in use. The recording was scheduled to stop at 10:03am and it did stop on time. But only one hour had been recorded. I looked in the log and saw that at about 9am, messages started repeating. I don't know what these messages mean.

Event start timestamp is 2020-11-23 07:59:00.018

Can anyone tell me what went wrong?

[mvallevand]

It looks like your post processing script hung leaving the status in limbo.

Martin

[jcole998]

Can you help me understand how you reached your conclusion?

I looked at the log and found the following:
2020-11-23 07:59:00.018 [DEBUG][9] Recording explicitly recording to directory: '[NPVRRemux]'
2020-11-23 07:59:00.018 [DEBUG][9] Preferred filename is 'A Cookie Cutter Christmas (2014)'
2020-11-23 07:59:00.018 [DEBUG][9] allocating recording target filename: g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts
2020-11-23 07:59:00.019 [DEBUG][9] About to start recording (73837 on 21): g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts...
2020-11-23 07:59:00.019 [DEBUG][9] (Recording is due to be stopped at 11/23/2020 10:00 AM)
2020-11-23 07:59:00.019 [DEBUG][9] Free space 111051710464  (g:\)
2020-11-23 07:59:00.019 [DEBUG][9] HDHomeRunRecorder.StartStream()
2020-11-23 07:59:00.019 [DEBUG][9] ipaddress is 192.168.1.155
2020-11-23 07:59:00.019 [DEBUG][9] building graph
2020-11-23 07:59:00.019 [DEBUG][9] About to load channel from tuning
2020-11-23 07:59:00.067 [DEBUG][9] source@3
2020-11-23 07:59:00.067 [DEBUG][9] Requesting: http://192.168.1.155:5004/tuner0/v740
2020-11-23 07:59:00.518 [DEBUG][9] Creating writer: g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts
2020-11-23 07:59:00.518 [DEBUG][67] HTTP input source starting
2020-11-23 07:59:00.520 [DEBUG][9] Created Mutex: Global\NPVR-mutex-17d7de7d1b5171eb774e862563233275
2020-11-23 07:59:00.520 [DEBUG][9] Created map: g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts.map
2020-11-23 07:59:00.520 [DEBUG][9] StartStream [g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts] allocated handle: 22
2020-11-23 07:59:00.520 [DEBUG][9] StartStream() returned handle=22
2020-11-23 07:59:00.521 [DEBUG][9] Allocated Handle: 22
2020-11-23 07:59:00.521 [DEBUG][9] Started recording (73837:22:g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts)
2020-11-23 07:59:00.595 [DEBUG][9] Starting: C:\Users\Public\NPVR-data\scripts\ParallelProcessing.bat "g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts" 740 73837 21 "A Cookie Cutter Christmas"
2020-11-23 07:59:01.351 [DEBUG][189] > Recording triggered - filename: ""g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts""
2020-11-23 07:59:01.358 [DEBUG][151] > --------------------- ChannelOID: 740  OID: 73837  DeviceOID: 21  Title: "A Cookie Cutter Christmas"
2020-11-23 07:59:04.106 [DEBUG][151] > NEXTPVR_INSTALLDIR C:\Program Files\NextPVR\
2020-11-23 07:59:04.106 [DEBUG][151] > NEXTPVR_DATADIR C:\Program Files\NextPVR\data\
2020-11-23 07:59:04.106 [DEBUG][151] > NEXTPVR_DATADIR_USERDATA C:\Users\Public\NPVR-data\
2020-11-23 09:02:46.807 [DEBUG][129] http://localhost:51167/status
2020-11-23 09:02:46.811 [DEBUG][129] <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
<Status>
  <Device oid="21" identifier="HDHomeRun Device 20200EC0">
    <Recording handle="150016">g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts</Recording>
  </Device>
  <Device oid="22" identifier="HDHomeRun Device 20200EC0">
  </Device>
  <Device oid="23" identifier="HDHomeRun Device 20200EC0">
  </Device>
  <Device oid="32" identifier="Hauppauge HD-PVR">
  </Device>
  <Device oid="36" identifier="EXTRA Recorder (extra-nasa.xml)">
  </Device>
  <Device oid="38" identifier="EXTRA Recorder (extra-Youtube.xml)">
  </Device>
</Status>
</rsp>

The ParallelProcessing.bat process is the one distributed with NextPVR with "start ...NextEnd.exe" added for sports. This is run every time a program is recorded. Why would it fail this time? Is there another log that can be looked at?

The first status occurred at 09:02:46. This is about the time that I signed in and looked at the tray icon status. From then until 10:03, these requests went unanswered. Did the port go dead? Did the NextPVR service crash? From the log, it seems that something reset the tuner. Is there a Windows event I can look for that might help?

One last thing...after the recording stopped, I immediately tried to view live TV just make sure all was well and the tuner light still worked. It took a really long time for the live TV picture to appear. I've never seen that before.

Hope you can help.

[mvallevand]

I said post not parallel processing. But i was wrong the it did complete it worked just not quickly So at 10:03 it was still processing.

2020-11-23 10:03:05.395 [DEBUG][14] > PostProcessing TRIGGERED - filename: "g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts"
....
2020-11-23 10:05:13.390 [DEBUG][47] > PostProcessing COMPLETE - filename: "g:\NextPVR-Remux\A Cookie Cutter Christmas (2014).ts"

By then you had already logged in worried prematurely I assum.

Martin

[jcole998]

I think we can agree that batch file processing is not the cause. Don't all those unanswered "2020-11-23 09:02:46.807 [DEBUG][129] http://localhost:51167/status" messages mean something? Did the 51167 port stop receiving? Did the tuner stop sending? 

The service recorded for two hours but the file stopped growing after one hour. The service continued to run for the second hour but no data was received or written. It sounds more and more like the tuner was reset for some reason.

I'm just trying to find out why the second hour of the recording is missing.  Next time it might be the final hour of the Daytona 500 . If this failure can't be explained, is there anything I can do to help trap it next time?

I appreciate your time. Thanks.

[mvallevand]

Since you were checking before the file had finished your remux I assumed that was the problem. What does the input file for your remux look like, to confirm that the source was not two hours

You can ignore the NTray statues messages they are just spam.

Do you get any status messages for your tuner http://192.168.1.155/log.html

Nothing here look like it was related to NextPVR but nothing can guarantee a full recording even on cable or via satellite.

Martin

[jcole998]

I played the file using NextPVR and VLC. Both programs and Windows Explorer all showed the file at just over an hour.

I did find the Hauppauge system log and browsed through it. The relevant times(EST-5) show:
20201123-00:59:01 Tuner: tuner2 tuning 507 WABC-DT (auto:519MHz-1029)
20201123-00:59:02 Tuner: tuner2 streaming http to 192.168.1.154:53371
20201123-00:59:02 CableCARD: tuner2 507 WABC-DT (auto:519MHz-1029) access = subscribed
20201123-02:59:59 Tuner: tuner0 tuning 739 Hallmark Movies (auto:561MHz-714)
20201123-03:00:00 Tuner: tuner0 streaming http to 192.168.1.154:61415
20201123-03:00:00 CableCARD: tuner0 739 Hallmark Movies (auto:561MHz-714) access = subscribed
20201123-10:00:13 CableCARD: message: Emergency message on TV - tune to channel 67.101
20201123-12:58:59 Tuner: tuner0 tuning 740 Hallmark Channe (auto:669MHz-807)
20201123-12:58:59 Tuner: tuner0 streaming http to 192.168.1.154:52494
20201123-12:59:00 CableCARD: tuner0 740 Hallmark Channe (auto:669MHz-807) access = subscribed
20201123-15:09:12 Tuner: tuner0 tuning 502 WCBS-DT (auto:507MHz-1025)
20201123-15:09:12 Tuner: tuner0 streaming http to 192.168.1.154:63185
20201123-15:09:12 CableCARD: tuner0 502 WCBS-DT (auto:507MHz-1025) access = subscribed
20201123-15:09:49 Tuner: tuner0 tuning 504 WNBC-DT (auto:519MHz-1027)
20201123-15:09:50 CableCARD: tuner0 504 WNBC-DT (auto:519MHz-1027) access = subscribed
20201123-15:09:50 Tuner: tuner0 streaming http to 192.168.1.154:63236

Recording started 8am local, data stopped an hour later and the file was closed at 10:03am. Nothing of interest in this log.

You're quite correct, Martin. There are no guarantees. I'm just glad it happens only rarely.

Thanks for you help.