MP stops recording before it is supposed to (1 Viewer)

[Doomblaster]

Okay...this has happened more and more often lately, and I can't really get to the bottom of this. Last time this happened was yesterday (08.09.2013). I had scheduled a recording from 21.29 to 22.35, and basically only 13 minutes and 50 seconds were recorded. I wasn't actually watching any other channel at that time, but I was using the HTPC to rent a movie online, so it was online streaming data. Other times this has happened, I have actually watched other channels, but MP has always indicated that it has been recording. Therefore it may look like similar to this issue: https://forum.team-mediaportal.com/...as-recording-but-doesnt-write-to-file.121429/. Before yesterdays recording I did actually turn on preloading the tuners though, so at least that isn't going to fix it for me.

Anyone able to decode anything from the logs?

My setup is single seat
Intel DH77EB
Intel 3770T
Intel X-25 SSD
8GB RAM
Digital Devices Cine CT V6 with 2 tuners and CAM

Surely this should be sufficient to run everything? It is working pretty well at least, except for the issue with recordings lately.

 

[mm1352000]

Hello Doomblaster

From TV Server's perspective, it recorded the full program:
[collapse]
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record TV Norge HD 21:29-22:30 Åndenes makt
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: find free card for channel TV Norge HD
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: find card for channel TV Norge HD
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: got 1 tuning details for TV Norge HD
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: channel #1 DVBC:tv:Canal Digital KTV TV Norge HD Freq:298000 ONID:70 TSID:6 SID:4103 PMT:0xB5 FTA:False LCN:6 SymbolRate:6950 Modulation:Mod256Qam
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:5 typevbC can tune to channel
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:3 typevbC can tune to channel
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:6 type:RadioWebStream cannot tune to channel
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:2 typevbS is disabled
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:4 typevbS is disabled
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: found 2 card(s) for channel
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 1 msec
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: found 2 free card(s)
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 1 msec
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=237, tuningdetails=DVBC:tv:Canal Digital KTV TV Norge HD Freq:298000 ONID:70 TSID:6 SID:4103 PMT:0xB5 FTA:False LCN:6 SymbolRate:6950 Modulation:Mod256Qam
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=238, tuningdetails=DVBC:tv:Canal Digital KTV TV Norge HD Freq:298000 ONID:70 TSID:6 SID:4103 PMT:0xB5 FTA:False LCN:6 SymbolRate:6950 Modulation:Mod256Qam
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:5 typevbC users: 1
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:5 typevbC is available
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:3 typevbC users: 0
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - Controller: card:3 typevbC is available
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - scheduler: try max 2 of 2 free cards for recording
[2013-09-08 21:29:07,512] [EPG ] [scheduler thread] [INFO ] - epg cancelled due to start recording
[2013-09-08 21:29:07,512] [EPG ] [scheduler thread] [INFO ] - epg grabber:epg cancelled
[2013-09-08 21:29:07,512] [EPG ] [scheduler thread] [INFO ] - EpgGrabbing: Stop - user epg
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - user:epg remove
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2013-09-08 21:29:07,512] [Log ] [scheduler thread] [INFO ] - DVB subch:0 Decompose()
[2013-09-08 21:29:07,527] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2013-09-08 21:29:07,527] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-09-08 21:29:07,527] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2013-09-08 21:29:07,527] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-09-08 21:29:07,527] [Log ] [scheduler thread] [INFO ] - dvbtopGraph
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - Controller: epg stop
[2013-09-08 21:29:07,549] [EPG ] [scheduler thread] [INFO ] - EPG: grabber stopped..
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - Scheduler : record, first tune to channel
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - card: Tune on card 3 to subchannel TV Norge HD
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [DEBUG] - card: user: scheduler263:3:-1 tune DVBC:tv:Canal Digital KTV TV Norge HD Freq:298000 ONID:70 TSID:6 SID:4103 PMT:0xB5 FTA:False LCN:6 SymbolRate:6950 Modulation:Mod256Qam
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - dvbc: TuneVBC:tv:Canal Digital KTV TV Norge HD Freq:298000 ONID:70 TSID:6 SID:4103 PMT:0xB5 FTA:False LCN:6 SymbolRate:6950 Modulation:Mod256Qam
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - dvbubmiting tunerequest Channel:TV Norge HD subChannel:-1
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - dvb:Getting new subchannel
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - dvb:GetNewSubChannel:0 #0
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - TvDvbChannel ctor new subchIndex:0
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - card: AddTuneEvent card: 3 / subch: 0
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - dvbubmit tunerequest size:1 new:0
[2013-09-08 21:29:07,549] [Log ] [scheduler thread] [INFO ] - subch:0 OnBeforeTune
[2013-09-08 21:29:07,564] [Log ] [scheduler thread] [INFO ] - dvbubmit tunerequest calling put_TuneRequest
[2013-09-08 21:29:07,564] [Log ] [scheduler thread] [INFO ] - dvbubmit tunerequest done calling put_TuneRequest
[2013-09-08 21:29:07,564] [Log ] [scheduler thread] [INFO ] - subch:0 OnAfterTune
[2013-09-08 21:29:07,564] [Log ] [scheduler thread] [INFO ] - RunGraph
[2013-09-08 21:29:07,564] [Log ] [scheduler thread] [INFO ] - subch:0 OnGraphStart
[2013-09-08 21:29:07,564] [Log ] [scheduler thread] [INFO ] - dvb: RunGraph
[2013-09-08 21:29:07,721] [Log ] [scheduler thread] [INFO ] - dvb: LockInOnSignal ok
[2013-09-08 21:29:07,721] [Log ] [scheduler thread] [INFO ] - subch:0 OnGraphStarted
[2013-09-08 21:29:07,721] [Log ] [scheduler thread] [INFO ] - subch:0 SetupPmtGrabberid B5 sid:1007
[2013-09-08 21:29:07,721] [Log ] [scheduler thread] [INFO ] - subch:0 set pmt grabber pmt:B5 sid:1007
[2013-09-08 21:29:07,721] [Log ] [scheduler thread] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
[2013-09-08 21:29:07,721] [Log ] [scheduler thread] [DEBUG] - WaitForPMT: Waiting for PMT B5
[2013-09-08 21:29:07,971] [Log ] [3 ] [INFO ] - subch:0 OnPMTReceived() pmt:B5 ran:True dynamic:False
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [DEBUG] - WaitForPMT: Found PMT after 0,2500509 seconds.
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 SendPmt:1007 1007 FFFFFFFF 2
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - Decode pmt
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 b 0 fd aa
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - descr2 pid:431 len:6 9 4 b 0 fd aa
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - Set descriptor data with length 6
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - descr2 pid:BFB len:6 9 4 b 0 fd aa
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - Set descriptor data with length 7
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 SendPMT version:2 len:67 4103
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [DEBUG] - Digital Devices:--> Setting service id 4103 for decrypting returned 0
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 cam flags:True
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 SetMpegPidMapping
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 pid:431 pcr
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 pid:B5 pmt
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 pid:431 video type:H.264
[2013-09-08 21:29:07,971] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:431 video type:H.264
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0 pid:BFB audio lang:nor type:MPEG-2
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:BFB audio lang:nor type:MPEG-2
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0 pid:178E teletext type:6
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:178E teletext type:6
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0 stop tif
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [DEBUG] - WaitForPmt: PMT handling took 0,0156262 seconds.
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [DEBUG] - card: Tuner locked: True
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - **************************************************
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 100 *****
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - **************************************************
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [DEBUG] - card: tuned user: scheduler263 subchannel: 0
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - user:scheduler263 add
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [DEBUG] - Scheduler: MakeFileName() using "moviesformat" (_isSerie=False)
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - Scheduler : record to C:\Users\Public\Recorded TV\Åndenes makt - TV Norge HD - 2013-09-08.ts
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - Controller: epg stop
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [DEBUG] - Recorder.start add audioVideoEventHandler
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - card: StartRecording 3 C:\Users\Public\Recorded TV\Åndenes makt - TV Norge HD - 2013-09-08.ts
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - StartRecording to C:\Users\Public\Recorded TV\Åndenes makt - TV Norge HD - 2013-09-08.ts
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0 StartRecord(C:\Users\Public\Recorded TV\Åndenes makt - TV Norge HD - 2013-09-08.ts)
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - subch:0-0 tswriter StartRecording...
[2013-09-08 21:29:07,986] [Log ] [scheduler thread] [INFO ] - SetRecorderPids
[2013-09-08 21:29:08,002] [Log ] [scheduler thread] [INFO ] - Set video / audio observer
[2013-09-08 21:29:08,018] [Log ] [scheduler thread] [INFO ] - DVB subch:0 Started recording
[2013-09-08 21:29:08,018] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
[2013-09-08 21:29:09,065] [Log ] [3 ] [INFO ] - PID seen - type = Video
[2013-09-08 21:29:09,065] [Log ] [3 ] [DEBUG] - Recorder audioVideoEventHandler Video
[2013-09-08 21:29:09,177] [Log ] [3 ] [INFO ] - PID seen - type = Audio
[2013-09-08 21:29:09,177] [Log ] [3 ] [DEBUG] - Recorder audioVideoEventHandler Audio
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - video and audio are seen after 1,1592707 seconds
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [INFO ] - TimeshiftingEPG: channel TV Norge HD is not configured for grabbing epg
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=238, tuningdetails=DVBC:tv:Canal Digital KTV TV Norge HD Freq:298000 ONID:70 TSID:6 SID:4103 PMT:0xB5 FTA:False LCN:6 SymbolRate:6950 Modulation:Mod256Qam
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [INFO ] - card: SignalTuneEvent card: 3 / subch: 0
[2013-09-08 21:29:09,177] [Log ] [Channel state thread] [DEBUG] - Controller: DoSetChannelStates for 198 channels
[2013-09-08 21:29:09,177] [Log ] [Channel state thread] [INFO ] - ChannelStates.DoSetChannelStates took 0 msec
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [DEBUG] - Scheduler: adding new row in db for title="Åndenes makt" of type="0"
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [INFO ] - Scheduler: recList: count: 1 add scheduleid: 263 card: Digital Devices DVB-C Tuner 2
[2013-09-08 21:29:09,177] [Log ] [scheduler thread] [DEBUG] - CardReservation.CancelCardReservation id=237
[2013-09-08 21:29:09,620] [Log ] [PowerScheduler poll thread] [DEBUG] - ActiveSharesHandler: Share monitoring is enabled.
[2013-09-08 21:30:10,728] [Log ] [PowerScheduler poll thread] [DEBUG] - ActiveSharesHandler: Share monitoring is enabled.
[2013-09-08 21:31:11,752] [Log ] [PowerScheduler poll thread] [DEBUG] - ActiveSharesHandler: Share monitoring is enabled.
[2013-09-08 21:32:12,797] [Log ] [PowerScheduler poll thread] [DEBUG] - ActiveSharesHandler: Share monitoring is enabled.
[2013-09-08 21:33:13,805] [Log ] [PowerScheduler poll thread] [DEBUG] - ActiveSharesHandler: Share monitoring is enabled.
[2013-09-08 22:35:13,753] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record TV Norge HD 08.09.2013 21:29:09-08.09.2013 22:30:00 Åndenes makt
[2013-09-08 22:35:13,753] [Log ] [scheduler thread] [INFO ] - card: StopRecording card=3, user=scheduler263
[2013-09-08 22:35:13,753] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch=0, subch index=0
[2013-09-08 22:35:13,753] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch:0-0 tswriter StopRecording...
[2013-09-08 22:35:13,753] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2013-09-08 22:35:13,753] [Log ] [scheduler thread] [INFO ] - DVB subch:0 Decompose()
[2013-09-08 22:35:13,768] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2013-09-08 22:35:13,768] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-09-08 22:35:13,768] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2013-09-08 22:35:13,768] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-09-08 22:35:13,768] [Log ] [scheduler thread] [INFO ] - dvbtopGraph
[2013-09-08 22:35:13,784] [Log ] [scheduler thread] [DEBUG] - usermanagement.RemoveUser: scheduler263, subch: 0 of 0, card: 3
[2013-09-08 22:35:13,784] [Log ] [scheduler thread] [INFO ] - user:scheduler263 remove
[2013-09-08 22:35:13,784] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2013-09-08 22:35:13,784] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-09-08 22:35:13,784] [Log ] [scheduler thread] [INFO ] - dvbtopGraph filterstate already stopped, returning.
[2013-09-08 22:35:13,784] [Log ] [scheduler thread] [INFO ] - Controller: epg start[/collapse]

...and nothing happened during the recording that could have stopped it.

I suspect the CAM is stops decrypting the program but right now I'm not sure why. Maybe something to do with your subscription. From other entries in your log file I suspect your CAM is trying to tell you something:

[2013-09-04 03:33:03,978] [Log ] [Digital Devices CiMenuHandler] [DEBUG] - Menu received (ID 2 Type 2 Choices 2)

Have you seen any of these messages?

mm

 

[Doomblaster]

Well...my subscription is working for sure. As I said, I've been watching TV while this has been happening as well, so it's not like it's stopped working. I haven't seen any of those lines either...not really sure where to look for it either. Got any pointers what this could mean? I'm totally clueless here to be honest.