Scheduled Recordings with 0 file size

[shortyjacobs]

This has been happening for a few weeks now at least. Files scheduled to record, status shows them recording, but the files end up having a file size of 0 bytes, (and obviously won't play).

Screenshot of the EPG with what I wanted to record last night attached. Superstore recorded just fine, and had an actual file size. I stopped Gotham from recording about halfway through, thinking it may be a padding issue with multiple channels. Both The Orville and Will and Grace recorded with 0 bytes.

Logs attached too.

NPVR seems to know something's up. After Superstore finishes recording, the Nrecord.log looks fine:

Code:

2017-10-12 19:00:32.161    [DEBUG][9]    Started recording (2337:2:E:\Recorded TV\Superstore\Superstore.S03E03.Part-Time.Hires.ts)
{SNIP}
2017-10-12 19:32:00.128    [DEBUG][9]    Stopping recording (2337 on 22). Past end time of recording. 2
2017-10-12 19:32:00.142    [DEBUG][9]    StopStream(2)
2017-10-12 19:32:00.663    [DEBUG][9]    StoreMetaData@1
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@2
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@3
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@4
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@5
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@6
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@7
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@8
2017-10-12 19:32:00.665    [DEBUG][9]    StoreMetaData@exit
2017-10-12 19:32:00.665    [DEBUG][9]    No C:\Users\Public\NPVR\Scripts\PostProcessing.bat

But the Orville displays stuff about "looking for alternative recordings":

Code:

017-10-12 19:59:00.040    [DEBUG][9]    DefaultDirectoryChoice: first
2017-10-12 19:59:00.040    [DEBUG][9]    Preferred filename is 'The.Orville.S01E06.Krill'
2017-10-12 19:59:00.040    [DEBUG][9]    allocating recording target filename: E:\Recorded TV\The Orville\The.Orville.S01E06.Krill.ts
2017-10-12 19:59:00.040    [DEBUG][9]    About to start recording (2339 on 20): E:\Recorded TV\The Orville\The.Orville.S01E06.Krill.ts...
2017-10-12 19:59:00.040    [DEBUG][9]    Free space 1434153472000  (E:\)
2017-10-12 19:59:00.040    [DEBUG][9]    Starting digital host
2017-10-12 19:59:00.747    [DEBUG][9]    Asking NDigitalHost to start: E:\Recorded TV\The Orville\The.Orville.S01E06.Krill.ts
2017-10-12 20:01:26.570    [DEBUG][9]    Temp at 10/12/2017 8:01:36 PM
2017-10-12 20:01:26.570    [DEBUG][9]    Started recording (2339:1:E:\Recorded TV\The Orville\The.Orville.S01E06.Krill.ts)
2017-10-12 20:01:26.576    [DEBUG][9]    No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2017-10-12 20:01:26.577    [DEBUG][36]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\The Orville _.jpg</Poster><Landscape>C:\Users\Public\NPVR\media\shows\The Orville _.landscape.jpg</Landscape><FanArt>C:\Users\Public\NPVR\media\shows\The Orville _.fanart.jpg</FanArt><Episode season="1" episode="4">none</Episode><Episode season="1" episode="5">none</Episode></Catalog>
2017-10-12 20:01:27.056    [DEBUG][54]    Done fanart.tv lookup
2017-10-12 20:32:00.120    [DEBUG][9]    Stopping recording (2341 on 22). Past end time of recording. 3
2017-10-12 20:32:00.135    [DEBUG][9]    StopStream(3)
2017-10-12 20:32:00.647    [DEBUG][9]    StoreMetaData@1
2017-10-12 20:32:00.648    [DEBUG][9]    StoreMetaData@2
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@3
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@4
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@5
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@6
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@7
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@8
2017-10-12 20:32:00.649    [DEBUG][9]    StoreMetaData@exit
2017-10-12 20:32:00.649    [DEBUG][9]    No C:\Users\Public\NPVR\Scripts\PostProcessing.bat
2017-10-12 21:02:00.227    [DEBUG][9]    Stopping recording (2339 on 20). Past end time of recording. 1
2017-10-12 21:02:00.230    [DEBUG][9]    Looking for alternative airings of The Orville *: Krill (The Orville *-S001E006)
2017-10-12 21:02:00.268    [DEBUG][9]    LoadListingByAdvancedRules(channel=7156,advancedRules=unique_id='The Orville *-S001E006')
2017-10-12 21:02:00.271    [DEBUG][9]    No alternatives on 9.1 KMSP-HD, so looking on other channels

Any advice?

[Graham]

The ndigitalhost.log.1 has ...

2017-10-11 18:58:02.491 [DEBUG][5] locked=1, present=1, strength=-10000, quality=100 (took 0ms to check)

and later ...

2017-10-12 19:00:30.801 [DEBUG][77] locked=0, present=0, strength=41000, quality=0 (took 47268ms to check)

It is the ndigitalhost process that connects to the tuner and receives the data. The ndigitalhost process appears to be saying that the input signal to the tuner disappeared between these two messages.

[mvallevand]

To me it looks like your tuner had a driver error when you cancelled Gotham

Code:

2017-10-12 19:23:16.940    [DEBUG][9]    StopStream(2)
2017-10-12 19:23:24.965    [ERROR][9]    Unexpected stopping remote stream: System.Runtime.Remoting.RemotingException: Failed to read from an IPC Port: The pipe has been ended.
...
2017-10-12 19:23:24.965    [ERROR][9]    Trying to force restart of NDigitalHost on next stream request...

....
2017-10-12 19:23:16.940    [INFO][116]    DigitalRecorder.StopStream() handle: 2
2017-10-12 19:23:16.940    [INFO][116]    No more streams active. Stopping device.
2017-10-12 19:23:16.940    [DEBUG][116]    About to request async graph stop
2017-10-12 19:23:16.941    [DEBUG][120]    Graph stopping... (async)
2017-10-12 19:23:24.940    [DEBUG][116]    Async stop taking way too long
2017-10-12 19:23:24.940    [DEBUG][116]    Stop() appeared to have failed. Exiting...
2017-10-12 19:23:24.941    [DEBUG][116]    Unregistering IPC host
2017-10-12 19:23:24.941    [INFO][116]    DigitalRecorder.StopHost()
2017-10-12 19:23:24.951    [DEBUG][116]    Trying CloseMainWindow()
2017-10-12 19:23:24.952    [DEBUG][116]    Trying Application.Exit()
2017-10-12 19:23:24.953    [DEBUG][116]    Trying Environment.Exit()

And it left your capture device in a bad state. I suggest a reboot.

Martin

[shortyjacobs]

I’ve had the problem for weeks, so it’s not just because I cancelled Gotham mid-stream, but reboots never hurt. I’ll give it a shot.

Thanks!

[mvallevand]

Right it doesn't fix the real problem for why the original failure occurred. Sub would have to determine if 8 seconds is truly "way too long" and if it is you'd have to see if more reliable drivers are available.

Martin

[sub]

It looks like it took 47 seconds for device to tell NextPVR the signal strength. That's crazy, and would definitely cause problems. It should take a few hundred milliseconds tops.

[mvallevand]

It looks like it took 47 seconds for device to tell NextPVR the signal strength. That's crazy, and would definitely cause problems. It should take a few hundred milliseconds tops.

That is later on in the failing digital host, it is the earlier crash in the previous instance of ndigitalhost which originally tuned quickly after the cancel at

2017-10-12 19:23:16.913 [DEBUG][63] CancelRecording(2335)

that I a think triggered it.