v3.1.1 can't execute back-to-back analog recordings, second fails

[Braklet]

I recently set up a back-to-back scheduled recording, with only a single analog source. Prior to v3.1.1 this worked well, and NRecord transitioned from recording 1 to recording 2 at recording 2's start time, eliminating my 5 minute pre- and post-recording buffers. Last night the first recording worked fine, but the second recording is missing. There is a second recording directory present, but it is empty. The first recording file timestamp seems to include a 5 minute post-recording buffer which I didn't expect. No "failed recording" shows up in the recording list, the second just vanishes from NPVR's database.

System is WinXP SP3 32 bit with a HVR-2250 card, satellite receiver output connected to one analog input. I attached the pertinent chunk of NRecord.log below (first recording = Archer, second recording = Chozen). Any ideas about what's going on?

Code:

2014-01-20 21:55:00.292    [DEBUG][7]    DefaultDirectoryChoice: first
2014-01-20 21:55:00.292    [DEBUG][7]    Advanced manual recurring recording is using name: Archer
2014-01-20 21:55:00.292    [DEBUG][7]    allocating recording target filename:

E:\Video\NPVR\Archer\Archer_20140120_22002231.ts
2014-01-20 21:55:00.292    [DEBUG][7]    About to start recording (8422 on 24):

E:\Video\NPVR\Archer\Archer_20140120_22002231.ts...
2014-01-20 21:55:00.292    [DEBUG][7]    Free space 370434588672  (E:\)
2014-01-20 21:55:00.292    [INFO][7]    AnalogRecorder.StartStream(E:\Video\NPVR\Archer\Archer_20140120_22002231.ts)
2014-01-20 21:55:00.292    [INFO][7]    AnalogRecorder stream count now 1
2014-01-20 21:55:00.292    [INFO][7]    Running blaster: C:\Devices\Hip\HIP\HipSend.exe 136 800
2014-01-20 21:55:02.714    [INFO][7]    Creating graph
2014-01-20 21:55:02.714    [DEBUG][7]    Building graph using: Hauppauge WinTV-7164 Analog Capture (1).
2014-01-20 21:55:02.792    [DEBUG][7]    about to look for encoder
2014-01-20 21:55:02.792    [DEBUG][7]    About to look for hardware encoder.
2014-01-20 21:55:02.807    [DEBUG][7]    AttachHardEncoder@1
2014-01-20 21:55:02.807    [DEBUG][7]    AttachHardEncoder@2 (got medium)
2014-01-20 21:55:02.932    [DEBUG][7]    AttachHardEncoder@3 (got encoder)
2014-01-20 21:55:02.948    [DEBUG][7]    AttachHardEncoder@4 (about to connect encoder)
2014-01-20 21:55:03.120    [DEBUG][7]    AttachHardEncoder@5 (connected encoder)
2014-01-20 21:55:03.136    [DEBUG][7]    AttachHardEncoder@6 (connected demux)
2014-01-20 21:55:03.151    [DEBUG][7]    about to add mux
2014-01-20 21:55:03.151    [DEBUG][7]    about to add tee
2014-01-20 21:55:03.151    [DEBUG][7]    about to connect writers
2014-01-20 21:55:03.151    [DEBUG][7]    Graph filter list:
2014-01-20 21:55:03.151    [DEBUG][7]     - NPVR Writer2
2014-01-20 21:55:03.151    [DEBUG][7]     - NPVR Writer
2014-01-20 21:55:03.151    [DEBUG][7]     - Infinite Pin Tee Filter
2014-01-20 21:55:03.151    [DEBUG][7]     - MainConcept (HCW) MPEG Multiplexer-Plus
2014-01-20 21:55:03.151    [DEBUG][7]     - MPEG-2 Demultiplexer
2014-01-20 21:55:03.151    [DEBUG][7]     - Hauppauge WinTV-7164 MPEG2 PS Encoder/Mux
2014-01-20 21:55:03.151    [DEBUG][7]     - Hauppauge WinTV-7164 Analog Capture
2014-01-20 21:55:03.151    [DEBUG][7]     - Hauppauge WinTV-7164 Analog Xbar
2014-01-20 21:55:03.151    [DEBUG][7]     - Hauppauge WinTV-7164 Analog TV Audio
2014-01-20 21:55:03.151    [DEBUG][7]     - Hauppauge WinTV-7164 Analog TV Tuner
2014-01-20 21:55:03.151    [DEBUG][7]    About to check crossbar routing
2014-01-20 21:55:03.151    [DEBUG][7]    SVideo: v-idx=3, a-idx=5
2014-01-20 21:55:03.167    [DEBUG][7]    Audio crossbar routed successfully
2014-01-20 21:55:03.167    [DEBUG][7]    Video crossbar already routed correctly
2014-01-20 21:55:03.167    [INFO][7]    About to start graph
2014-01-20 21:55:03.167    [DEBUG][7]    device minimum bitrate: 0
2014-01-20 21:55:03.167    [DEBUG][7]    device maximum bitrate: 6000000
2014-01-20 21:55:03.167    [DEBUG][7]    device bitrate step size: 1
2014-01-20 21:55:03.182    [DEBUG][7]    device reports current bitrate as: 6000000
2014-01-20 21:55:03.182    [DEBUG][7]    device reports current peak bitrate as: 6000000
2014-01-20 21:55:03.182    [DEBUG][7]    About to set BITRATE MODE
2014-01-20 21:55:03.198    [DEBUG][7]    requesting variable encoding
2014-01-20 21:55:03.229    [DEBUG][7]    trying to request bitrate: 4820000
2014-01-20 21:55:03.245    [DEBUG][7]    device confirms bitrate as: 4820000
2014-01-20 21:55:03.245    [DEBUG][7]    About to set PEAK BITRATE
2014-01-20 21:55:03.261    [DEBUG][7]    device minimum peak bitrate: 0
2014-01-20 21:55:03.261    [DEBUG][7]    device maximum peak bitrate: 9500000
2014-01-20 21:55:03.261    [DEBUG][7]    device peak bitrate step size: 1
2014-01-20 21:55:03.261    [DEBUG][7]    trying to request peak bitrate: 9500000
2014-01-20 21:55:03.276    [DEBUG][7]    device confirms bitrate as: 9500000
2014-01-20 21:55:03.479    [DEBUG][7]    About to tune graph to:
<tuning>
  <type>Analog</type>
  <locator>
    <channel>136</channel>
    <country>1</country>
    <input>cable</input>
    <source>SVideo</source>
    <fixed>2</fixed>
  </locator>
</tuning>

2014-01-20 21:55:03.479    [DEBUG][7]    About to check crossbar routing
2014-01-20 21:55:03.479    [DEBUG][7]    SVideo: v-idx=3, a-idx=5
2014-01-20 21:55:03.495    [DEBUG][7]    Audio crossbar routed successfully
2014-01-20 21:55:03.495    [DEBUG][7]    Video crossbar already routed correctly
2014-01-20 21:55:03.495    [DEBUG][7]    About to switch AnalogRecorder to target:
E:\Video\NPVR\Archer\Archer_20140120_22002231.ts
2014-01-20 21:55:03.495    [DEBUG][7]    Temp at 1/20/2014 9:55:13 PM
2014-01-20 21:55:03.495    [DEBUG][7]    Started recording (8422:19:E:\Video\NPVR\Archer\Archer_20140120_22002231.ts)
2014-01-20 21:55:03.511    [DEBUG][7]    No C:\Documents and Settings\All Users\Application

Data\NPVR\Scripts\ParallelProcessing.bat
2014-01-20 22:26:00.151    [DEBUG][7]    Recording due to start pre-padding, but tuner not available
2014-01-20 22:26:00.151    [DEBUG][7]    Scheduled recording is supposed to start on tuner currently being used for

live tv. Need to look for alternative tuner.
2014-01-20 22:26:00.151    [DEBUG][7]    Unable to find alternative tuner. Live TV will be stopped.
2014-01-20 22:26:00.463    [DEBUG][7]    Recording due to start pre-padding, but tuner not available
2014-01-20 22:26:00.463    [DEBUG][7]    Scheduled recording is supposed to start on tuner currently being used for

live tv. Need to look for alternative tuner.

[5 minutes of these debug messages, repeated every second]

2014-01-20 22:31:00.205    [DEBUG][7]    Unable to find alternative tuner. Live TV will be stopped.
2014-01-20 22:31:00.205    [DEBUG][7]    DefaultDirectoryChoice: first
2014-01-20 22:31:00.205    [DEBUG][7]    allocating recording target filename:

E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts
2014-01-20 22:31:00.205    [DEBUG][7]    About to start recording (8420 on 24):

E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts...
2014-01-20 22:31:00.205    [DEBUG][7]    Free space 369067245568  (E:\)
2014-01-20 22:31:00.205    [INFO][7]    AnalogRecorder.StartStream(E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts)
2014-01-20 22:31:00.205    [INFO][7]    AnalogRecorder reuse stream. count still 1
2014-01-20 22:31:00.205    [INFO][7]    Running blaster: C:\Devices\Hip\HIP\HipSend.exe 136 800
2014-01-20 22:31:03.924    [DEBUG][7]    About to tune graph to:
<tuning>
  <type>Analog</type>
  <locator>
    <channel>136</channel>
    <country>1</country>
    <input>cable</input>
    <source>SVideo</source>
    <fixed>2</fixed>
  </locator>
</tuning>

2014-01-20 22:31:03.924    [DEBUG][7]    About to check crossbar routing
2014-01-20 22:31:03.924    [DEBUG][7]    SVideo: v-idx=3, a-idx=5
2014-01-20 22:31:03.924    [DEBUG][7]    Audio crossbar routed successfully
2014-01-20 22:31:03.924    [DEBUG][7]    Video crossbar already routed correctly
2014-01-20 22:31:03.924    [DEBUG][7]    About to switch AnalogRecorder to target:
E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts
2014-01-20 22:31:03.924    [DEBUG][7]    Temp at 1/20/2014 10:31:13 PM
2014-01-20 22:31:03.924    [DEBUG][7]    Started recording (8420:20:E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts)
2014-01-20 22:31:03.940    [DEBUG][7]    Invalid file passed to StartParallelProcessing():

'E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts'
2014-01-20 22:36:00.010    [DEBUG][7]    Stopping recording (8422 on 24). Past end time of recording. 19
2014-01-20 22:36:00.010    [DEBUG][7]    Starting: C:\Documents and Settings\All Users\Application

Data\NPVR\Scripts\PostProcessing.bat "E:\Video\NPVR\Archer\Archer_20140120_22002231.ts" 136 8422 24 "Archer"
2014-01-20 23:07:00.275    [DEBUG][7]    Stopping recording (8420 on 24). Past end time of recording. 20
2014-01-20 23:07:00.275    [INFO][7]    AnalogRecorder stream count now 0
2014-01-20 23:07:00.275    [DEBUG][7]    Graph stopping...
2014-01-20 23:07:00.634    [DEBUG][7]    Graph stopped
2014-01-20 23:07:00.634    [DEBUG][7]    Removing filter  NPVR Writer2
2014-01-20 23:07:00.634    [DEBUG][7]    Removing filter  NPVR Writer
2014-01-20 23:07:00.838    [DEBUG][7]    Removing filter  Infinite Pin Tee Filter
2014-01-20 23:07:00.838    [DEBUG][7]    Removing filter  MainConcept (HCW) MPEG Multiplexer-Plus
2014-01-20 23:07:00.838    [DEBUG][7]    Removing filter  MPEG-2 Demultiplexer
2014-01-20 23:07:00.838    [DEBUG][7]    Removing filter  Hauppauge WinTV-7164 MPEG2 PS Encoder/Mux
2014-01-20 23:07:00.838    [DEBUG][7]    Removing filter  Hauppauge WinTV-7164 Analog Capture
2014-01-20 23:07:00.853    [DEBUG][7]    Removing filter  Hauppauge WinTV-7164 Analog Xbar
2014-01-20 23:07:00.853    [DEBUG][7]    Removing filter  Hauppauge WinTV-7164 Analog TV Audio
2014-01-20 23:07:00.853    [DEBUG][7]    Removing filter  Hauppauge WinTV-7164 Analog TV Tuner
2014-01-20 23:07:00.963    [DEBUG][7]    Invalid file passed to StartPostProcessing():

'E:\Video\NPVR\Chozen\Chozen_20140120_22312302.ts'

[Braklet]

Nobody else seen this?

[SilverTiger]

Nobody else seen this?

Sorry for late reply. Yes, I'm having the same issue. Once it sort of worked, but last time, same as you, I got nothing for the second recording.

[johnsonx42]

yeah, there are some bugs with this; afaik this will never happen if you don't use padding. Pre-padding is worse than post-padding, but either can lead to problems. One relates to the fact that an HVR-2250's 2 tuners can be analog OR digital, but NPVR sees them as 4 distinct tuners; the DeviceRules.xml file defines which tuners conflict with each other, but NPVR does not process that in all situations (like when handling padding); this can lead to a scenario where NPVR believes it's able to start a recording early with padding when no tuner is actually available, and then when the recording fails to start it just fails the whole recording rather than trying again at the proper recording time. Another issue that sometimes leads to a problem is that when NPVR ends a recording early to do another recording, it doesn't explicilty end the first recording but rather just switches the tuner away; in most cases this causes no problem other than slightly confusing log messages (i.e. a log entry later that says it's ending a recording that actually ended several minutes ago), but sometimes it leads to the second recording being no good.

As I have an HVR-2250 and can replicate these issues, I will try to get fixes for these during pre-release testing for NPVR 3.2.

[SilverTiger]

yeah, there are some bugs with this; afaik this will never happen if you don't use padding. Pre-padding is worse than post-padding, but either can lead to problems. One relates to the fact that an HVR-2250's 2 tuners can be analog OR digital, but NPVR sees them as 4 distinct tuners; the DeviceRules.xml file defines which tuners conflict with each other, but NPVR does not process that in all situations (like when handling padding); this can lead to a scenario where NPVR believes it's able to start a recording early with padding when no tuner is actually available, and then when the recording fails to start it just fails the whole recording rather than trying again at the proper recording time. Another issue that sometimes leads to a problem is that when NPVR ends a recording early to do another recording, it doesn't explicilty end the first recording but rather just switches the tuner away; in most cases this causes no problem other than slightly confusing log messages (i.e. a log entry later that says it's ending a recording that actually ended several minutes ago), but sometimes it leads to the second recording being no good.

As I have an HVR-2250 and can replicate these issues, I will try to get fixes for these during pre-release testing for NPVR 3.2.

I have Colossus; same issue. I have set all padding to zero, but does not help.