REDUX: Can't Skip Analog Recordings After v2.5.9->3.1.1 Upgrade

[Braklet]

A few weeks ago, I experienced a problem skipping ahead in currently-recording ATSC broadcasts. Sub found a timing problem that only affects XP users like myself.

Well, it happened again last night, except this time the culprit was an analog recording from my HVR-2250 card. Same symptoms as before, with an "Unhandled Exception" popup from npvr.exe. I checked NPVR.log and found evidence similar to that reported before.

Code:

2014-01-12 21:02:42.727    [DEBUG][1]    Playing video file: E:\Video\NPVR\Worlds Dumbest\Worlds Dumbest_20140112_20002100.ts
2014-01-12 21:02:42.742    [DEBUG][1]    Using 'NPVR TS Reader2'
2014-01-12 21:02:42.742    [DEBUG][1]    File in use. Maybe still recording.
2014-01-12 21:02:42.742    [DEBUG][1]    Timing.info reports duration 4056594ms
2014-01-12 21:02:42.805    [DEBUG][1]    RenderDemux()
2014-01-12 21:02:42.805    [DEBUG][1]    Adding system HE-AAC decoder
2014-01-12 21:02:42.805    [DEBUG][1]    Adding system AC3 decoder
2014-01-12 21:02:42.805    [DEBUG][1]    Adding system MPEG1 Layer2 decoder
2014-01-12 21:02:42.805    [DEBUG][1]    about to load decoder
2014-01-12 21:02:42.883    [DEBUG][1]    added decoder to graph
2014-01-12 21:02:42.883    [DEBUG][1]    adding audio renderer: Default DirectSound Device
2014-01-12 21:02:42.992    [DEBUG][1]    Adding system E-AC3 decoder
2014-01-12 21:02:43.008    [DEBUG][1]    Adding system MPEG2 decoder
2014-01-12 21:02:43.008    [DEBUG][1]    Adding VMR9 Custom renderer
2014-01-12 21:02:43.024    [DEBUG][1]    DISPLAYMODE: 1920x1080  60
2014-01-12 21:02:43.039    [DEBUG][1]    CAllocator::AddRef (m_refCount=2)
2014-01-12 21:02:43.039    [DEBUG][1]    CAllocator::AddRef (m_refCount=3)
2014-01-12 21:02:43.039    [DEBUG][1]    CAllocator::AddRef (m_refCount=4)
2014-01-12 21:02:43.055    [DEBUG][1]    about to load decoder
2014-01-12 21:02:43.133    [DEBUG][1]    added decoder to graph
2014-01-12 21:02:43.195    [ERROR][1]    ConnectPins: Failed to find output pin named ~CC
2014-01-12 21:02:43.195    [ERROR][1]    ConnectPins: Failed to find output pin named ~CC Out
2014-01-12 21:02:43.242    [DEBUG][1]    Static Reference clock set to: MPEG1 Audio Renderer
2014-01-12 21:02:43.742    [DEBUG][1]    restoring last aspect ratio
2014-01-12 21:02:43.742    [DEBUG][1]    Source Aspect Ratio: 704x576
2014-01-12 21:02:43.742    [DEBUG][1]    Playback graph running...
2014-01-12 21:02:43.742    [DEBUG][1]    Graph filter list:
2014-01-12 21:02:43.742    [DEBUG][1]     - NPVR CC Dump
2014-01-12 21:02:43.742    [DEBUG][1]     - Video Mixing Renderer 9
2014-01-12 21:02:43.742    [DEBUG][1]     - NPVR PES Collector (Teletext)
2014-01-12 21:02:43.742    [DEBUG][1]     - NPVR PES Collector (DVBSubs)
2014-01-12 21:02:43.742    [DEBUG][1]     - MPEG1 Audio Renderer
2014-01-12 21:02:43.742    [DEBUG][1]     - Line 21 Decoder
2014-01-12 21:02:43.742    [DEBUG][1]     - NVIDIA Audio Decoder
2014-01-12 21:02:43.742    [DEBUG][1]     - NVIDIA Video Decoder
2014-01-12 21:02:43.742    [DEBUG][1]     - MPEG-2 Demultiplexer
2014-01-12 21:02:43.742    [DEBUG][1]     - NPVR TS Reader2
2014-01-12 21:02:44.789    [DEBUG][1]    ActivatePopup: null
2014-01-12 21:02:44.789    [DEBUG][1]    deactivating old popup: ShowDetailsPopup
2014-01-12 21:02:44.789    [DEBUG][1]    Going to dispose popup at end of animation
2014-01-12 21:02:44.789    [DEBUG][1]    OnKeyDown() done. Took 2062.447265625 ms
2014-01-12 21:02:44.789    [DEBUG][1]    GetEventCode() returned: 0x000d
2014-01-12 21:02:44.789    [DEBUG][1]    GetEventCode() returned: 0x000e
2014-01-12 21:02:44.789    [DEBUG][1]    audio renderer now MPEG1
2014-01-12 21:02:44.789    [DEBUG][1]    Dynamic reference clock set to: MPEG1 Audio Renderer
2014-01-12 21:02:44.789    [DEBUG][1]    Reference clock was already se correctly. No change required.
2014-01-12 21:02:44.789    [DEBUG][1]    GetEventCode() returned: 0x8102
2014-01-12 21:02:44.789    [DEBUG][1]    Aspect ratio now: 4x3
2014-01-12 21:02:44.789    [DEBUG][1]    Resolution is now: 720x480
2014-01-12 21:02:44.789    [DEBUG][1]    Source Aspect Ratio: 4x3
2014-01-12 21:02:44.789    [DEBUG][1]    GetEventCode() returned: 0x8101
2014-01-12 21:02:44.789    [DEBUG][1]    GetEventCode() returned: 0x8065
[...]
2014-01-12 21:02:44.789    [DEBUG][1]    GetEventCode() returned: 0x8065
2014-01-12 21:02:44.805    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:44.805    [DEBUG][1]    Updating OSD.
2014-01-12 21:02:44.898    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:45.008    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:45.055    [DEBUG][1]    Calling dispose on old popup(2): ShowDetailsPopup
2014-01-12 21:02:45.055    [DEBUG][1]    ShowDetailsPopup.Dispose()
2014-01-12 21:02:45.055    [DEBUG][1]    UiStatic.Dispose()
2014-01-12 21:02:45.117    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:45.227    [DEBUG][1]    GetDuration returning 0
[...]
2014-01-12 21:02:48.227    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: E40352)
2014-01-12 21:02:48.227    [DEBUG][1]    OnKeyDown() called: {CTRL}Right, Control
2014-01-12 21:02:48.242    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:48.242    [DEBUG][1]    User is trying to skip.
2014-01-12 21:02:48.242    [DEBUG][1]    Current position is: 4.49723863601685
2014-01-12 21:02:48.242    [DEBUG][1]    Asking for position: -2
2014-01-12 21:02:48.242    [DEBUG][1]    Pause()
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition(-2.000000)
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap2
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap3
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap4
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap5
2014-01-12 21:02:48.258    [DEBUG][1]    Using timing.info, jumping to time -2.000000 (offset 0)
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap6
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@skipmap7
2014-01-12 21:02:48.258    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:48.258    [DEBUG][1]    after skip disk offset 4230000
2014-01-12 21:02:48.258    [DEBUG][1]    SetPosition@exit
2014-01-12 21:02:48.258    [DEBUG][1]    Play()
2014-01-12 21:02:48.273    [DEBUG][1]    skippedWhilePaused enabled (position: 4.51263475418091)
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition(4.712635)
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap2
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap3
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap4
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap5
2014-01-12 21:02:48.273    [DEBUG][1]    Using timing.info, jumping to time 4.712635 (offset 2401700)
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap6
2014-01-12 21:02:48.273    [DEBUG][1]    SetPosition@skipmap7
2014-01-12 21:02:48.445    [DEBUG][1]    GetEventCode() returned: 0x000e
2014-01-12 21:02:48.445    [DEBUG][1]    raw message: 0
2014-01-12 21:02:48.461    [DEBUG][1]    GetDuration returning 0
[...]
2014-01-12 21:02:48.836    [DEBUG][1]    Hiding OSD.
2014-01-12 21:02:48.945    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:49.055    [DEBUG][1]    GetDuration returning 0
[...]
2014-01-12 21:02:55.289    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:55.320    [DEBUG][1]    OnKeyDown() called: Escape
2014-01-12 21:02:55.320    [DEBUG][1]    About to store playback position information
2014-01-12 21:02:55.320    [DEBUG][1]    GetDuration returning 0
2014-01-12 21:02:55.320    [DEBUG][1]    PlaybackPositionHelper.StorePlaybackPosition(Worlds

Dumbest_20140112_20002100.ts, 4, 0)
2014-01-12 21:02:55.320    [DEBUG][1]    PlaybackPositionHelper.DeletePlaybackPosition(E:\Video\NPVR\Worlds

Dumbest\Worlds Dumbest_20140112_20002100.ts)
2014-01-12 21:02:55.336    [DEBUG][1]    Stopping graph@1

Again, I'm running NPVR v3.1.1 on a HTPC with XP SP3 and all current updates. Let me know if I can extract anything else helpful to the fix.

TIA!

[johnsonx42]

did you check the timing.info for that analog recording? it's probably got the same 0 timestamps throughout.

the timing data for analog recordings is generated in a different program (NPVRWriter.ax) than for digital recordings; sub likely had the same problematic snippet of code in that one, which fails on XP systems.

[johnsonx42]

oh, just realized sub probably can't make a patch for 3.1.1 any more. if not, you can probably use this one here: http://forums.nextpvr.com/showthread.php...post467068, or get the original one from the 3.1.1 installer.

[Braklet]

did you check the timing.info for that analog recording? it's probably got the same 0 timestamps throughout.

the timing data for analog recordings is generated in a different program (NPVRWriter.ax) than for digital recordings; sub likely had the same problematic snippet of code in that one, which fails on XP systems.

Timing.info for that same file looks OK, of course this is many hours since it finished recording:

Code:

0,0
891,361900
1797,658000
2703,1118600
3672,1743700
4578,2401700
5469,2993900
6453,3586100
7344,4244100
8219,4836300
9110,5428500
10016,5922000
10906,6547100
11891,7205100
12781,7797300
13688,8290800
14563,8784300
15453,9475200
[...]

What's interesting is that NPVR.log indicates that "GetDuration returning 0" and "Using timing.info, jumping to time -2.000000 (offset 0)" in response to my attempts to skip ahead. This time the analog timing.info looks correct, but npvr.exe is doing something that seems to cause another div/0 exception.

[Braklet]

oh, just realized sub probably can't make a patch for 3.1.1 any more. if not, you can probably use this one here: http://forums.nextpvr.com/showthread.php...post467068, or get the original one from the 3.1.1 installer.

Uh oh, so does that mean v3.1.1 is orphaned? Considering that my analog recordings have good timing.info I don't think overwriting NPVRWriter.ax will have any effect.

Thanks!

[Braklet]

Wonder if this is another case of GetTickCount64 versus GetTickCount as described here? Although that was in reference to NPVRTSMon.ax, so I doubt it.

[sub]

Wonder if this is another case of GetTickCount64 versus GetTickCount as described here? Although that was in reference to NPVRTSMon.ax, so I doubt it.

See if this helps for new recordings.

[Braklet]

See if this helps for new recordings.

I'll give it a try tonight!

Many thanks for the help, sub.

[Braklet]

See if this helps for new recordings.

Skipping back and forth in an analog Quick Record seems to work fine. Thanks again, sub.

[Braklet]

Hi johnsonx42, don't know if you're still rolling update collections but might want to add NPVRWriter.ax from this thread. Thanks!