NRECORD cancelled a recording-in-progress because I deleted a previous recording

[johnsonx42]

Ok, this one is bizarre:

at 9:00pm NRECORD started recording "Last Comic Standing", recording id 3953:

Code:

2010-08-09 21:00:00.363    [DEBUG][6]    About to start recording (3953): F:\Recordings\Last Comic Standing\Last Comic Standing_20100809_21002300.ts
... all the recording starting messages ...
2010-08-09 21:00:05.657    [INFO][6]    DigitalRecorder.StartStream() allocated handle: 0x1
2010-08-09 21:00:05.658    [DEBUG][6]    Temp at 8/9/2010 9:00:15 PM
2010-08-09 21:00:05.658    [DEBUG][6]    Started recording (3953:F:\Recordings\Last Comic Standing\Last Comic Standing_20100809_21002300.ts)

then at about 9:08pm I decide to clean house on the completed "America's Got Talent" recordings that have all been watched, which as always also caused it to reload the recording schedule:

Code:

2010-08-09 21:08:32.760    [DEBUG][3]    DeleteRecording(3389)
2010-08-09 21:08:32.760    [DEBUG][3]    Cancelling wake up request for for 'RecordingOID3389'
2010-08-09 21:08:32.833    [DEBUG][3]     -removing: F:\Recordings\Americas Got Talent\Americas Got Talent_20100803_21002300.ts
2010-08-09 21:08:33.320    [DEBUG][3]    PlaybackPositionHelper.DeletePlaybackPosition(F:\Recordings\Americas Got Talent\Americas Got Talent_20100803_21002300.ts)
2010-08-09 21:08:33.562    [DEBUG][6]    Reloading recording schedule
2010-08-09 21:08:33.577    [DEBUG][6]    Requesting wake up for 'RecordingOID3953' at 8/9/2010 8:58 PM
.... all the rest of the recording schedule is listed, all is ok ....

oh, but what's this at the end of the reload?:

Code:

2010-08-09 21:08:33.580    [ERROR][6]    Unexpected orphaned recording found (3839). Stopping it...
2010-08-09 21:08:33.580    [INFO][6]    DigitalRecorder.StopStream() handle: 1
2010-08-09 21:08:33.581    [INFO][6]    No more streams active. Stopping device.
2010-08-09 21:08:33.581    [DEBUG][6]    Graph stopping...
2010-08-09 21:08:33.713    [DEBUG][6]    Graph stopped
2010-08-09 21:08:33.713    [DEBUG][6]    Removing filter  BDA MPEG2 Transport Information Filter
2010-08-09 21:08:33.714    [DEBUG][6]    Removing filter  MPEG-2 Demultiplexer
2010-08-09 21:08:33.714    [DEBUG][6]    Removing filter  NPVR TS Mon
2010-08-09 21:08:33.716    [DEBUG][6]    Removing filter  Capture
2010-08-09 21:08:33.717    [DEBUG][6]    Removing filter  Tuner
2010-08-09 21:08:33.717    [DEBUG][6]    Removing filter  Network Provider

I have no idea what this 'orphan' recording 3839 was, I can't find it in any of the NRECORD logs (the logs fill up too much with GetQuality() messages), but when it thought it was stopping that it actually tore down the graph for "Last Comic Standing". The 2 hour recording is only 8 minutes and 30 seconds long (and it was timestamped at 9:08pm).

I deleted a couple more recordings, and each time the same orphan recording 3839 shows up at the end of the reload.

When 11:00pm rolled around, it still thought it was recording 3953, and it thinks it ends that without incident (along with a Seinfeld (3903) that started at 10:30pm):

Code:

2010-08-09 23:00:00.153    [DEBUG][6]    Stopping recording (3953). Past end time of recording.
2010-08-09 23:00:00.153    [INFO][6]    DigitalRecorder.StopStream() handle: 1
2010-08-09 23:00:00.254    [DEBUG][6]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\Recordings\Last Comic Standing\Last Comic Standing_20100809_21002300.ts" 4
2010-08-09 23:00:00.325    [DEBUG][6]    Stopping recording (3903). Past end time of recording.
2010-08-09 23:00:00.325    [INFO][6]    DigitalRecorder.StopStream() handle: 1
2010-08-09 23:00:00.325    [INFO][6]    No more streams active. Stopping device.
2010-08-09 23:00:00.325    [DEBUG][6]    Graph stopping...
2010-08-09 23:00:00.325    [DEBUG][6]    Graph stopped
2010-08-09 23:00:00.325    [DEBUG][6]    Removing filter  BDA MPEG2 Transport Information Filter
2010-08-09 23:00:00.325    [DEBUG][6]    Removing filter  MPEG-2 Demultiplexer
2010-08-09 23:00:00.325    [DEBUG][6]    Removing filter  NPVR TS Mon
2010-08-09 23:00:00.325    [DEBUG][6]    Removing filter  Capture
2010-08-09 23:00:00.325    [DEBUG][6]    Removing filter  Tuner
2010-08-09 23:00:00.333    [DEBUG][6]    Removing filter  Network Provider
2010-08-09 23:00:00.637    [DEBUG][6]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\Recordings\Seinfeld\Seinfeld_20100809_22302300.ts" 13

I *think* restarting the recording service will get rid of this ghost-of-recordings-past 3839, but this sort of housekeeping shouldn't tear down the graph of a current recording.

[johnsonx42]

a quick followup, I did just look at the resource monitor on the NPVR box, and the only recording file being written to right now is a current recording in progress; there is no orphaned graph still writing to another file.

and a little more followup, I checked the resouce monitor again when no 'real' recordings were in progress, and now the only file open other than windows system stuff is the npvr web log (due to the fact that I'm running the NPVR Status gadget on my desktop).

[johnsonx42]

The reload of the recording schedule following the EPG update overnight still showed the mysterious orphan recording 3839, so this morning I restarted the recording service and now 3839 appears to be gone.