v.1.5.33 dies unexpectedly when beginning playing recording on PCH

[BrettB]

I upgraded to v. 1.5.33 earlier today. It has been working fairly well.

But I just had a problem when I tried to play a recording of Chuck on the PCH. NPVR seemed to be starting to play the video, but then it died unexpectedly and mvpmxc2 on the PCH also shutdown.

Looking in the mvp.log.1 file, I see the following which looks "odd":

Code:

2010-10-15 20:03:51.609    [DEBUG][3]    User pressed: Return
2010-10-15 20:03:51.659    [DEBUG][3]    Looking for Timing.Info
2010-10-15 20:03:51.709    [DEBUG][3]    Sending Timing.Info
2010-10-15 20:03:51.709    [DEBUG][3]    StartVideoPlayback: D:\NPVR Videos\Chuck\Chuck_20101004_19002000.ts
2010-10-15 20:03:51.709    [DEBUG][3]    Sent playback request
2010-10-15 20:03:51.709    [DEBUG][3]    Sent 'Hide OSD' request
2010-10-15 20:03:51.719    [DEBUG][3]    CheckCache() indicates:C:\Users\Public\NPVR\Media\Shows\Chuck.jpg is cached
2010-10-15 20:03:51.719    [DEBUG][3]    CheckCache() indicates:C:\Users\Public\NPVR\Media\Shows\Chuck.jpg is cached
2010-10-15 20:03:51.749    [DEBUG][3]    OnKeyDown() complete
2010-10-15 20:03:51.749    [DEBUG][3]    MVP request processed
2010-10-15 20:03:51.749    [DEBUG][3]    MVP waiting for data
2010-10-15 20:03:51.819    [DEBUG][7]    Received: STREAM_REQUEST
2010-10-15 20:03:51.819    [DEBUG][7]    Requested file: System.Byte[] (D:\NPVR Videos\Chuck\Chuck_20101004_19002000.ts)
2010-10-15 20:03:51.819    [DEBUG][7]    Playback on PCH
2010-10-15 20:03:51.819    [DEBUG][7]    RollingFile(D:\NPVR Videos\Chuck\Chuck_20101004_19002000.ts)
2010-10-15 20:03:51.819    [DEBUG][7]    SharedMemoryHelper::Open()
2010-10-15 20:03:51.819    [DEBUG][7]    Unable to find in 'Global', about to check 'Local'
2010-10-15 20:03:51.819    [DEBUG][7]    Unable to find in either 'Global' or 'Local'
2010-10-15 20:03:51.819    [DEBUG][7]    about to read 20032 from location 0  (current length = 6063384272)
2010-10-15 20:03:51.819    [DEBUG][7]    about to read 32000 from location 0  (current length = 6063384272)
2010-10-15 20:03:51.819    [DEBUG][7]    about to read 84600 from location 0  (current length = 6063384272)
2010-10-15 20:03:51.819    [DEBUG][7]    about to read 84600 from location 84600  (current length = 6063384272)
2010-10-15 20:03:51.819    [DEBUG][7]    about to read 84600 from location 169200  (current length = 6063384272)
2010-10-15 20:03:51.819    [DEBUG][7]    about to read 84600 from location 253800  (current length = 6063384272)
2010-10-15 20:03:51.859    [DEBUG][7]    about to read 84600 from location 338400  (current length = 6063384272)
2010-10-15 20:03:51.859    [DEBUG][7]    about to read 84600 from location 423000  (current length = 6063384272)
2010-10-15 20:03:51.859    [DEBUG][7]    about to read 84600 from location 507600  (current length = 6063384272)
2010-10-15 20:03:51.859    [DEBUG][7]    about to read 84600 from location 592200  (current length = 6063384272)
2010-10-15 20:03:51.879    [DEBUG][7]    about to read 84600 from location 676800  (current length = 6063384272)
2010-10-15 20:03:51.879    [DEBUG][7]    about to read 84600 from location 761400  (current length = 6063384272)
2010-10-15 20:03:51.879    [DEBUG][7]    about to read 84600 from location 6063384272  (current length = 6063384272)
2010-10-15 20:03:51.879    [DEBUG][7]    Not all bytes read@1. About to do second chance
2010-10-15 20:03:51.879    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:03:52.129    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:03:52.379    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:03:52.629    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:03:52.879    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:04:05.489    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:04:05.769    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:04:06.019    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:04:06.269    [DEBUG][7]    Waiting for file to grow
2010-10-15 20:04:06.519    [DEBUG][7]    Waiting for file to grow

I'm attaching all of the log files.

I don't think that there is a problem with the recording itself because when I restarted NPVR on the PCH, and went back in to play the same recording, it started just fine. (You should be able to see that in the mvp.log file.)

[mvallevand]

It does look odd. NPVR seems to be timing out trying to read 84600 bites from the EOF. In another example, after 5 seconds it timed out and then it rewinds a bit.

Code:

2010-10-15 19:12:57.266    [DEBUG][7]    about to read 84600 from location 6709097720  (current length = 6709097720)
2010-10-15 19:12:57.266    [DEBUG][7]    Not all bytes read@1. About to do second chance
...
2010-10-15 19:13:01.016    [DEBUG][7]    Not all bytes read@2
2010-10-15 19:13:01.016    [DEBUG][7]    Read() didnt get all bytes. Got 0 of 84600 bytes requested.
2010-10-15 19:13:01.016    [DEBUG][7]    about to read 84600 from location 6709013120  (current length = 6709097720)

Martin

[mvallevand]

I was able to do some testing and I see this new 5 second wait on all my recordings and older files too. It doesn't explain why it didn't time out in that one case.

Martin

[BrettB]

I just had this problem occur again. This time I got a putty log from the PCH before restarting mvpmcx2. Maybe it will tell Martin something new.

[mvallevand]

I just had this problem occur again. This time I got a putty log from the PCH before restarting mvpmcx2. Maybe it will tell Martin something new.

No nothing new, it looks like it is stopping at the server side. I see it is also getting in the way of resume. These are the risks sub make in releasing something with a very limited testing, but it is beta. You probably have to go back to GBPVR to avoid this for the next few weeks.

Martin

[BrettB]

Bump.

[sub]

Give this patch a go.

[BrettB]

Give this patch a go.

With this patch, we go back to the old behavior where the npvr server just expectedly dies and restarts and where mvpmcx2 on the PCH just hangs with a black screen and forces a complete reboot of the PCH. Logs attached. (The attempted playing of "The Defenders".) Again, after the PCH reboots, I can go right back into npvr and successfully play the recording.

[mvallevand]

Logs?

Martin

[BrettB]

Logs?

Martin

Oopps. Sorry. Attached.