split recordings when scheduled recording happens while watching live tv

[Oliver.Freyd@…]

When a recording is scheduled while I watch live tv, if I choose to watch it while recording, I always get 2 recordings, the first one is 1 or 2 minutes short, the second one is the rest of the movie.

I'm running mythtv with 2 DVB-S cards as input, using EPG as video source. Here is a mythtvbackend log: As one can easily see, it repeats the same messages about "finished recording" and "expiring program" several time. The "desperate housewives" gets recorded for about 90 seconds, could it be something like an EPG update that makes it split the recording to a new file?

2011-03-23 20:13:00.613 LoadFromScheduler(): Error, called from backend.
2011-03-23 20:13:00.628 Scheduled 38 items in 0.2 = 0.00 match + 0.19 place
2011-03-23 20:13:00.645 scheduler: Scheduled items: Scheduled 38 items in 0.2 = 0.00 match + 0.19 place
2011-03-23 20:13:29.840 TVRec(1): ASK_RECORDING 1 29 0 0
2011-03-23 20:13:30.486 TVRec(2): ASK_RECORDING 2 29 0 0
2011-03-23 20:14:02.947 AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
2011-03-23 20:14:02.948 Started recording: "Desperate Housewives": channel 18501 on cardid 1, sourceid 1
2011-03-23 20:14:02.951 scheduler: Started recording: "Desperate Housewives": channel 18501 on cardid 1, sourceid 1
2011-03-23 20:14:03.284 TVRec(1): HW Tuner: 1->1
2011-03-23 20:14:03.773 LoadFromScheduler(): Error, called from backend.
2011-03-23 20:14:03.777 AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
2011-03-23 20:14:03.976 Finished recording Tagesschau: channel 29111
2011-03-23 20:14:03.979 scheduler: Finished recording: Tagesschau: channel 29111
2011-03-23 20:14:04.047 DVBSM(/dev/dvb/adapter0/frontend0), Warning: Cannot count Uncorrected Blocks
                        eno: Die angeforderte Funktion ist nicht implementiert (38)
2011-03-23 20:14:04.874 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17507) desired(17501)
2011-03-23 20:14:04.921 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17508) desired(17501)
2011-03-23 20:14:05.052 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17504) desired(17501)
2011-03-23 20:14:05.096 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17503) desired(17501)
2011-03-23 20:14:05.096 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17502) desired(17501)
2011-03-23 20:14:05.097 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17506) desired(17501)
2011-03-23 20:14:05.097 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17505) desired(17501)
2011-03-23 20:14:05.097 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17500) desired(17501)
2011-03-23 20:14:05.440 Finished recording Desperate Housewives: channel 18501
2011-03-23 20:14:05.492 scheduler: Finished recording: Desperate Housewives: channel 18501
2011-03-23 20:14:05.558 AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
2011-03-23 20:14:05.679 Finished recording Desperate Housewives: channel 18501
2011-03-23 20:14:07.406 RecBase(1:/dev/dvb/adapter0/frontend0): GetKeyframePositions(13,9223372036854775807,#1) out of 2
2011-03-23 20:14:07.651 RecBase(1:/dev/dvb/adapter0/frontend0): GetKeyframePositions(13,9223372036854775807,#1) out of 2
2011-03-23 20:14:08.575 MainServer::ANN Monitor
2011-03-23 20:14:08.575 adding: galileo as a client (events: 0)
2011-03-23 20:14:08.576 MainServer::ANN Monitor
2011-03-23 20:14:08.583 adding: galileo as a client (events: 1)
2011-03-23 20:15:32.825 Reschedule requested for id -1.
2011-03-23 20:15:33.504 Scheduled 38 items in 0.7 = 0.45 match + 0.22 place
2011-03-23 20:15:33.504 DVBChan(3:/dev/dvb/adapter1/frontend0) Warning: Unsupported fec_inner parameter.
2011-03-23 20:15:33.558 scheduler: Last message repeated 1 times: Finished recording: Desperate Housewives: channel 18501
2011-03-23 20:15:33.562 scheduler: Scheduled items: Scheduled 38 items in 0.7 = 0.45 match + 0.22 place
2011-03-23 20:15:33.729 TVRec(1): HW Tuner: 1->1
2011-03-23 20:15:33.771 Updating status for "Desperate Housewives" on cardid 1 (Recording => Recorded)
2011-03-23 20:15:33.772 Finished recording Desperate Housewives: channel 18501
2011-03-23 20:15:33.787 Reschedule requested for id 0.
2011-03-23 20:15:33.787 Reschedule requested for id 0.
2011-03-23 20:15:33.805 scheduler: Finished recording: Desperate Housewives: channel 18501
2011-03-23 20:15:33.826 AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
2011-03-23 20:15:33.839 recording already exists...
2011-03-23 20:15:33.860 Finished recording Desperate Housewives: channel 18501
2011-03-23 20:15:33.971 Scheduled 38 items in 0.2 = 0.01 match + 0.17 place
2011-03-23 20:15:34.015 scheduler: Last message repeated 1 times: Finished recording: Desperate Housewives: channel 18501
2011-03-23 20:15:34.025 MainServer::ANN Monitor
2011-03-23 20:15:34.067 adding: galileo as a client (events: 0)
2011-03-23 20:15:34.045 DVBSM(/dev/dvb/adapter1/frontend0), Warning: Cannot count Uncorrected Blocks
                        eno: Die Operation wird nicht unterstützt (95)
2011-03-23 20:15:34.069 MainServer::ANN Monitor
2011-03-23 20:15:34.070 adding: galileo as a client (events: 1)
2011-03-23 20:15:34.070 TVRec(1): RingBufferChanged()
2011-03-23 20:15:34.073 Finished recording Desperate Housewives: channel 18501
2011-03-23 20:15:34.097 New DB connection, total: 5
2011-03-23 20:15:34.085 scheduler: Scheduled items: Scheduled 38 items in 0.2 = 0.01 match + 0.17 place
2011-03-23 20:15:34.098 Connected to database 'mythconverg' at host: localhost
2011-03-23 20:15:34.100 scheduler: Finished recording: Desperate Housewives: channel 18501
2011-03-23 20:15:36.283 RecBase(1:/dev/dvb/adapter0/frontend0): GetKeyframePositions(37,9223372036854775807,#0) out of 3
2011-03-23 20:16:34.930 Expiring 0 MB for 18501 at 2011-03-23T20:14:03 => "Desperate Housewives"
2011-03-23 20:16:34.933 autoexpire: Expiring Program: Expiring 0 MB for 18501 at 2011-03-23T20:14:03 => "Desperate Housewives"

[danielk]

We're going to need the full log, or at least a much larger snippet before and after, to decipher this. Multiple Finish Recordings are annoying but not the cause of any problems. Multiple StartRecording? calls could cause this, but there is only one in the log.

I see some problems in this log, notably:

  2011-03-23 20:13:00.613 LoadFromScheduler(): Error, called from backend.

and

2011-03-23 20:14:04.874 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17507) desired(17501)
2011-03-23 20:14:04.921 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17508) desired(17501)
2011-03-23 20:14:05.052 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17504) desired(17501)
2011-03-23 20:14:05.096 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17503) desired(17501)
2011-03-23 20:14:05.096 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17502) desired(17501)
2011-03-23 20:14:05.097 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17506) desired(17501)
2011-03-23 20:14:05.097 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17505) desired(17501)
2011-03-23 20:14:05.097 DTVSM(/dev/dvb/adapter0/frontend0) Error: Wrong PMT; pmt->pn(17500) desired(17501)

But those don't match the symptom you've described.

Can you provide a complete log -v record,channel log which exhibits this problem? (That is run "mythbackend -v record,channel" reproduce the problem and then shut down the backed. Preferably with the mythtv-rec2 branch, but if not tell just me what version you are using.)

[robertm]

No response in a month, and unable to reproduce.