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

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!

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.

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.

johnsonx42 Wrote: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.

johnsonx42 Wrote: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!

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.

Braklet Wrote: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.

sub Wrote:See if this helps for new recordings.

I'll give it a try tonight!

Many thanks for the help, sub.

sub Wrote:See if this helps for new recordings.

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

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