Problem with NextPVR and automatic skipping playing on NMT

[BrettB]

Earlier this morning, I encountered a new problem. I was watching Big Brother and things seemed to be playing fine. It was about half over, did a commercial skip, began playing again after the commercial, then ended playback and went back to the recordings list. I wasn’t paying that much attention, and thought that it was at the end of the episode and comskip had just cut off the last "teaser" segment. So I tried playing it again and skipping to the end. (I had to do it a couple of times, so you’ll see that in the logs.) Then I discovered, that it had NOT actually been at the end. I kept skipping back to find the point where it had ended prematurely, and found that it was just after the commercial skip at 28 minutes in. This time, when I let it keep playing for a minute or so, it went on just fine. I then stopped playback to get logs which are attached. I’ve also included the timing and comskip files.

Martin has already looked at the logs and his response is:

mvpmcx2 is doing what it was told and at ~10:46 in the MVP log, NPVR told it to seek to 3653 seconds, so I think NextPVR was using wrong comskip point, I don't see anything else there.

So, it appears to be a problem with NextPVR. Sub, can you please take a look?

[sub]

If you play it again, does it make the same incorrect commerical skip? If so, I could probably add some more logging.

[BrettB]

If you play it again, does it make the same incorrect commerical skip? If so, I could probably add some more logging.

If I just start it at the beginning and let it play through to that 28 minute point, then it is reproducible. However, if I start it playing and then try to manually skip ahead 27 or so minutes, then it plays, does the commercial skip, and continues on just fine.

[sub]

Were there earlier commercial skips that went correctly, or was this the first one?

[sub]

Reproduce the problem with this patch, then post the mvp.log and I'll take a look.

[mvallevand]

Were there earlier commercial skips that went correctly, or was this the first one?

His edl file is

Code:

985.78    1144.08    0
1728.96    1897.66    0
2142.67    2330.83    0
2931.83    3113.98    0
3390.75    3653.42    0

It did the seek to 1144 ok, but the seek to 1897 was quickly followed with the seek to 3653

Code:

2011-07-09 10:46:23.795    [DEBUG][3]    Sending seek request to MVP/NMT. current position = 1897, duration = 3659
2011-07-09 10:46:23.795    [DEBUG][7]    Received: STREAM_SEEK
2011-07-09 10:46:23.795    [DEBUG][7]    RollingFile.Position returning 2219842022
2011-07-09 10:46:23.795    [DEBUG][7]    Stream Length: 7101338664
2011-07-09 10:46:23.795    [DEBUG][7]    Stream Duration: 3659.689
2011-07-09 10:46:23.795    [DEBUG][7]    requestedPositionInSeconds: 1897
2011-07-09 10:46:23.795    [DEBUG][7]    Set position to:3680979297
2011-07-09 10:46:23.795    [DEBUG][7]    RollingFile.Seek(3680979297)
2011-07-09 10:46:23.795    [DEBUG][7]    about to read 300000 from location 3680979297  (current length = 7101338664)
2011-07-09 10:46:23.826    [DEBUG][3]    MVP data read: 1   (7)
2011-07-09 10:46:23.826    [DEBUG][3]    Got ACK
2011-07-09 10:46:23.826    [DEBUG][3]    MVP request processed
2011-07-09 10:46:23.826    [DEBUG][3]    MVP waiting for data
2011-07-09 10:46:23.826    [DEBUG][3]    MVP data read: 1   (9)
2011-07-09 10:46:23.826    [DEBUG][3]    Raw PTS received:78070493
2011-07-09 10:46:23.826    [DEBUG][3]    Reported PTS now:78046469  time: 1734.36597777778
2011-07-09 10:46:23.826    [DEBUG][3]    MVP request processed
2011-07-09 10:46:23.826    [DEBUG][3]    MVP waiting for data
2011-07-09 10:46:23.826    [DEBUG][7]    Received request to seek to pos:3680979297
2011-07-09 10:46:23.826    [DEBUG][7]    RollingFile.Seek(3680979297)
2011-07-09 10:46:23.826    [DEBUG][7]    RollingFile.Position returning 3680979297
2011-07-09 10:46:23.920    [DEBUG][3]    Sending 'Play' Request
2011-07-09 10:46:23.920    [DEBUG][3]    Sending seek request to MVP/NMT. current position = 3653, duration = 3659
2011-07-09 10:46:23.951    [DEBUG][3]    MVP data read: 1   (7)

Martin

[sub]

BrettB, can you try reproduce it with this patch and post the log. It adds a couple more messages than that previous patch.

[BrettB]

BrettB, can you try reproduce it with this patch and post the log. It adds a couple more messages than that previous patch.

Sub,

Here are logs from playback with this patch. You will notice that I had to play it through to that 28 minute problem point twice.

The first time, it worked fine and just kept playing. The only thing that I could think of that was different (besides your patched NextPVR.exe) was that I had the timeline OSD displayed so that I could see when it was getting to the point and immediately after the 2nd commercial skip right before the "problem" skip request being sent to mvpmcx2.

So, I stopped the playback and started it again. This time, I just let it run and didn't do any displays of the OSD. And, then it behaved as before by doing that 2nd commercial skip, beginning to play again, and then skipping to the end of the file and going back to the recordings list. So, apparently, having the OSD on seems to make it "fix" it.

[sub]

Sorry - a bit more logging. Please rerproduce again and repost the log.

[BrettB]

Sorry - a bit more logging. Please rerproduce again and repost the log.

OK, here's the latest log file. I started the play, then skipped to 25 minutes in, but made sure not to have the OSD on when it did the commercial skip at 28 minutes. And it reproduced the problem of ending right after that skip resumed.