Recording length changing for previously recorded show

[BrettB]

I recorded and then watched The Amazing Race: Unfinished Business tonight. Note, the recording was completely finished before I began playing it. However, I think that comskip was still processing it when I started it on the PCH the first time.

When I first watched it, I was using the PCH and noticed that it showed the length of the recording as 01:13:45. It should have been a 1-hour show plus either 1 or 3 minutes of padding (depending upon whether the post-padding was honored).

When the playback got to the end of the program, mvpmcx2 hung displaying a frame of video. I'm guessing that the hang was caused by npvr reporting the length of the program as 01:13:45, but the file is actually only about 01:03:00, and when mvpmcx2 tried to go past the end of the file, it had problems.

I then tried playing it on the pc. On there, the length kept changing fluxuating between 01:15:00 and 01:07:00 or so. (I only played about 5 minutes, so I don't know if it would have stopped changing at some point or not.)

I've attached logs. The timing.info is from this recording. The putty.log is the info from the PCH for the time when it hung. The npvr.log is from playing it on the pc. Unfortunately, when the PCH hung, it was using an mvp server which wasn't logging, so I don't have the original log from it. But I did go back and begin playing it on the PCH and got an mvp.log which shows beginning playing the file.

[sub]

However, I think that comskip was still processing it when I started it on the PCH the first time.

Was the problem still there when comskip finished running?

[BrettB]

Was the problem still there when comskip finished running?

Yes. The problem is still there now and is consistently reproducible.

[sub]

From your symptoms, it sounds like it's not finding timing.info - so it falls back to having to guess the duration based on the bit rate.

You can check its definitely using timing.info by playing a file on the PC, then skipping and checking you get a "Using timing.info, jumping to time..." type message in npvr.log. If you dont get that, then its gettings based on bitrate (which is changing).

[mvallevand]

It was using Timing.Info.

Out of curiousity does the PC version report a long time too? If you look at the putty.log, one of the changes I did was to fake a last Timing.Info when NPVR reports a longer duration time, In this case it reports about 650 seconds difference

New timings 3779 7800963072
...
New timings 4425 7801208832

BrettB I also see this message

Code:

2011-03-13 21:29:03.131    [DEBUG][3]    Handling PLAYBACK_ENDED
2011-03-13 21:29:03.131    [DEBUG][3]    PLAYBACK_ENDED@2.0
2011-03-13 21:29:03.201    [DEBUG][3]    trying to force complete refresh2
2011-03-13 21:29:03.471    [DEBUG][3]    TrackEnded()
2011-03-13 21:29:03.481    [ERROR][3]    Unexpected error handling PLAYBACK_ENDED: System.NullReferenceException: Object reference not set to an instance of an object.
   at NextPVR.Players.MusicPlaybackManager.TrackEnded()
   at NextPVR.MVP.MVPServerForm.ControlThread()

Do you have sub's latest NextPVR that was supposed to solve this?

I might also need the last 100MB of this file to see what is going on.

Martin

[BrettB]

[quote=sub]From your symptoms, it sounds like it's not finding timing.info - so it falls back to having to guess the duration based on the bit rate.[QUOTE]

@Sub,

From the npvr.log file I included, I'm guessing that the indication of the problem is the line:

Code:

2011-03-13 21:21:50.007    [DEBUG][1]    File in use. Maybe still recording.

I used Process Explorer and see that NRecord process still has a handle to the file now.

[BrettB]

Out of curiousity does the PC version report a long time too?

@mvallevand: On the PC, the length keeps changing. It seemed to be varying between the 01:07:00 or so and 01:15:00 or so. It changes every couple of seconds.

Do you have sub's latest NextPVR that was supposed to solve this?

I guess I'm not sure. As I recall, I've put in one patched NextPVR image since 2.0.3 was released. I'm also a little confused by it saying the error was from "...MusicPlaybackManager.TrackEnded()" since I only very rarely play any music with NextPVR/mvpmcx2 and definitely didn't tonight.

[BrettB]

BrettB I also see this message

Code:

2011-03-13 21:29:03.131    [DEBUG][3]    Handling PLAYBACK_ENDED
2011-03-13 21:29:03.131    [DEBUG][3]    PLAYBACK_ENDED@2.0
2011-03-13 21:29:03.201    [DEBUG][3]    trying to force complete refresh2
2011-03-13 21:29:03.471    [DEBUG][3]    TrackEnded()
2011-03-13 21:29:03.481    [ERROR][3]    Unexpected error handling PLAYBACK_ENDED: System.NullReferenceException: Object reference not set to an instance of an object.
   at NextPVR.Players.MusicPlaybackManager.TrackEnded()
   at NextPVR.MVP.MVPServerForm.ControlThread()

Do you have sub's latest NextPVR that was supposed to solve this?

Martin,

I found this thread where you reporting the same error

Great. The value is stored, the resume button disappears and as a bonus there is a full refresh of the screen. I do see this log message that might simply be there because of the extra logging, music isn't playing here.

Code:

2011-03-06 19:18:26.917    [DEBUG][3]    trying to force complete refresh2
2011-03-06 19:18:27.169    [DEBUG][3]    TrackEnded()
2011-03-06 19:18:27.169    [ERROR][3]    Unexpected error handling PLAYBACK_ENDED: System.NullReferenceException: Object reference not set to an instance of an object.
   at NextPVR.Players.MusicPlaybackManager.TrackEnded()
   at NextPVR.MVP.MVPServerForm.ControlThread()

But I don't see a new version of NextPVR there that's supposed to fix it.

[BrettB]

I used Process Explorer and see that NRecord process still has a handle to the file now.

Upon further investigation, it appears that the process which had the handle to the file was a subprocess of the NRecord process--specifically one of the MVP servers which had hung when mvpmcx2 hung.

I killed that process and then the pc reports the proper length of 01:02:59. However, on the PCH, the OSD timeline still reports a length of 01:13:45. So NextPVR.exe doesn't seem to be using the timing.info when running as an MVP server.

[mvallevand]

Sorry BrettB I forgot that error is still there.

Martin