MVP Forward Skip during recording show problem

[Major Hostility]

I was watching a show that was still recording last night and found a problem at one point when I tried to skip forward during a commercial break.

I was trying to do a basic 1s skip forward, but it ended up skipping quite a bit further. When I reviewed the log file, it looks like it failed to call mvpVideoDuration before it computed the skip distance so it skipped to the wrong location.

Here are the relevant log sections:

Code:

... here is the last skip from the previous commercial break
   ... note that the stream duration is set at 2869

10/17/2005 8:46:50 PM.093    VERBOSE    [57]    Request 200000 bytes (file size:2166824896   file location: 1547143240)
10/17/2005 8:46:50 PM.093    VERBOSE    [57]    about to check
10/17/2005 8:46:50 PM.093    VERBOSE    [57]    ...livetv mode
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    MVP data read: 1   (4)
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    User pressed: 15
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    Skipping forward: 1
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    mvpVideoDuration: 2869
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    MVPSetPlaybackPosition() request to set position to: 2057 seconds
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    MVP not sending frame
10/17/2005 8:46:50 PM.109    VERBOSE    [56]    MVP request processed
10/17/2005 8:46:50 PM.171    VERBOSE    [56]    MVP data read: 1   (9)
10/17/2005 8:46:50 PM.171    VERBOSE    [56]    PACK9: 0000005C3A9588000000
10/17/2005 8:46:50 PM.171    VERBOSE    [56]    MVP request processed
10/17/2005 8:46:50 PM.281    VERBOSE    [57]    Stream Length: 2166939584
10/17/2005 8:46:50 PM.281    VERBOSE    [57]    Stream Duration: 2869
10/17/2005 8:46:50 PM.281    VERBOSE    [57]    requestedPositionInSeconds: 2057
10/17/2005 8:46:50 PM.281    VERBOSE    [57]    Set position to:1553640545
10/17/2005 8:46:50 PM.296    VERBOSE    [57]    Received request to seek to pos:1553640545
10/17/2005 8:46:50 PM.328    VERBOSE    [57]    Request 200000 bytes (file size:2166958016   file location: 1553640545)

   ... 5 minutes of regular show viewing log data omitted here

10/17/2005 8:51:49 PM.796    VERBOSE    [57]    Request 200000 bytes (file size:2392690624   file location: 1782840545)
10/17/2005 8:51:49 PM.796    VERBOSE    [57]    about to check
10/17/2005 8:51:49 PM.796    VERBOSE    [57]    ...livetv mode
10/17/2005 8:51:49 PM.875    VERBOSE    [56]    MVP data read: 1   (9)
10/17/2005 8:51:49 PM.875    VERBOSE    [56]    PACK9: 0000006A470A21000000
10/17/2005 8:51:49 PM.875    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:50 PM.031    VERBOSE    [57]    Request 200000 bytes (file size:2392862656   file location: 1783040545)
10/17/2005 8:51:50 PM.031    VERBOSE    [57]    about to check
10/17/2005 8:51:50 PM.031    VERBOSE    [57]    ...livetv mode
10/17/2005 8:51:50 PM.062    VERBOSE    [56]    MVP data read: 1   (4)

   ... here is a skip forward at the beginning of the next commercial break
   ... note that we don't see a call to mvpVideoDuration
   ... and that the Stream Duration value is the same as it was
   ... 5 minutes earlier although Stream Length has updated to
   ... reflect newly recorded material

10/17/2005 8:51:50 PM.062    VERBOSE    [56]    User pressed: 43
10/17/2005 8:51:50 PM.062    VERBOSE    [56]    Skipping forward: 1
10/17/2005 8:51:50 PM.062    VERBOSE    [56]    MVPSetPlaybackPosition() request to set position to: 2390 seconds
10/17/2005 8:51:50 PM.062    VERBOSE    [56]    MVP not sending frame
10/17/2005 8:51:50 PM.062    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:50 PM.359    VERBOSE    [56]    MVP data read: 1   (9)
10/17/2005 8:51:50 PM.359    VERBOSE    [56]    PACK9: 0000006A4A1761000000
10/17/2005 8:51:50 PM.359    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:50 PM.437    VERBOSE    [57]    Stream Length: 2393169856
10/17/2005 8:51:50 PM.437    VERBOSE    [57]    Stream Duration: 2869
10/17/2005 8:51:50 PM.437    VERBOSE    [57]    requestedPositionInSeconds: 2390
10/17/2005 8:51:50 PM.437    VERBOSE    [57]    Set position to:1993613090
10/17/2005 8:51:50 PM.453    VERBOSE    [57]    Received request to seek to pos:1993613090
10/17/2005 8:51:50 PM.484    VERBOSE    [57]    Request 200000 bytes (file size:2393206720   file location: 1993613090)
10/17/2005 8:51:50 PM.484    VERBOSE    [57]    about to check
10/17/2005 8:51:50 PM.484    VERBOSE    [57]    ...livetv mode
10/17/2005 8:51:50 PM.546    VERBOSE    [57]    Request 200000 bytes (file size:2393288640   file location: 1993813090)
10/17/2005 8:51:50 PM.546    VERBOSE    [57]    about to check
10/17/2005 8:51:50 PM.546    VERBOSE    [57]    ...livetv mode
10/17/2005 8:51:50 PM.546    VERBOSE    [56]    MVP data read: 1   (9)
10/17/2005 8:51:50 PM.546    VERBOSE    [56]    PACK9: 00000076D72C62000000
10/17/2005 8:51:50 PM.546    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:50 PM.578    VERBOSE    [56]    MVP data read: 1   (7)
10/17/2005 8:51:50 PM.578    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:50 PM.640    VERBOSE    [56]    MVP data read: 1   (9)
10/17/2005 8:51:50 PM.640    VERBOSE    [56]    PACK9: 00000076DA39A2000000
10/17/2005 8:51:50 PM.640    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:50 PM.640    VERBOSE    [57]    Request 200000 bytes (file size:2393405376   file location: 1994013090)

   ... Request 200000 bytes entries removed to shorten log

   ... At this point I realized we had skipped forward too far
   ... and requested a back skip
   ... Note that mvpVideoDuration is called this time, and that
   ... the duration is now correct

10/17/2005 8:51:53 PM.406    VERBOSE    [57]    Request 200000 bytes (file size:2395647936   file location: 1998013090)
10/17/2005 8:51:53 PM.406    VERBOSE    [57]    about to check
10/17/2005 8:51:53 PM.406    VERBOSE    [57]    ...livetv mode
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    MVP data read: 1   (4)
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    User pressed: 14
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    Skipping back: 1
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    mvpVideoDuration: 3173
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    MVPSetPlaybackPosition() request to set position to: 2636 seconds
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    MVP not sending frame
10/17/2005 8:51:53 PM.625    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:53 PM.765    VERBOSE    [56]    MVP data read: 1   (9)
10/17/2005 8:51:53 PM.765    VERBOSE    [56]    PACK9: 000000771A4FE2000000
10/17/2005 8:51:53 PM.765    VERBOSE    [56]    MVP request processed
10/17/2005 8:51:53 PM.859    VERBOSE    [57]    Stream Length: 2395971520
10/17/2005 8:51:53 PM.859    VERBOSE    [57]    Stream Duration: 3173
10/17/2005 8:51:53 PM.859    VERBOSE    [57]    requestedPositionInSeconds: 2636
10/17/2005 8:51:53 PM.859    VERBOSE    [57]    Set position to:1990476182
10/17/2005 8:51:53 PM.875    VERBOSE    [57]    Received request to seek to pos:1990476182
10/17/2005 8:51:53 PM.906    VERBOSE    [57]    Request 200000 bytes (file size:2395987904   file location: 1990476182)

[Major Hostility]

Hey sub I know you're just getting back from break and all, but I was hoping you could take a quick look at the log I posted and let me know if I mis-interpreted something, or if I've tracked down a bug.

Thanks for the great program, and all your time and effort to continue improving it!

[sub]

Do you use comclean?

[Major Hostility]

Do you use comclean?

Nope. I do use comskip, but only after the show is complete, so it hadn't started up yet for this episode.

[sub]

Can you zip and attach the complete log file from above if you have it?

[Major Hostility]

Can you zip and attach the complete log file from above if you have it?

Here's the compressed log I had saved. I believe it represents the entire MVP session from when I first turned on the MVP device until we turned it off after watching the show.

[sub]

Unfortunately that is missing the beginning of the log.

What version of GB-PVR are you using?

[Major Hostility]

Yeah. Sorry about that. I think the original log spanned several days and I just chopped out the section for that viewing session.

I'm currently running:

10/22/2005 8:21:46 AM.156 VERBOSE [2] getValue: /settings/Version : GB-PVR v0.94.13

Would a copy of the startup log from today be helpful at all?

[sub]

When you started playing this recording which was still recording, where did you start playback from - recording screen, or video library?

[Major Hostility]

I'm pretty sure it was from Recordings -> What's New. I only have a couple of shows under "Video Library" that are shows not recorded by GB-PVR.