MythTV fails to start scheduled recording

[lyricnz@…]

My mythbox randomly fails to start recordings, leaving the following error messages in the backend log:

2006-07-17 01:00:02.749 TVRec(1): Changing from RecordingOnly to None
2006-07-17 01:00:02.957 Finished recording 2006 Formula One Grand Prix "Round 11 - France": channel 1010
2006-07-17 01:00:03.292 Finished recording 2006 Formula One Grand Prix "Round 11 - France": channel 1010
2006-07-17 01:00:03.445 TVRec(1): Changing from None to RecordingOnly
2006-07-17 01:00:03.475 TVRec(1) Error: Failed to set channel to . Reverting to kState_None
2006-07-17 01:00:03.489 TVRec(1): Changing from RecordingOnly to None
2006-07-17 01:00:03.493 Finished recording Moto Gp: channel 1001
2006-07-17 01:00:03.499 Started recording: Moto Gp: channel 1001 on cardid 1, sourceid 1
2006-07-17 01:00:04.525 Reschedule requested for id 0.
2006-07-17 01:00:04.698 Scheduled 15 items in 0.2 = 0.00 match + 0.17 place

Looking at the source where that error message is emitted, The same system seems to start "xine dvb://" every time, so perhaps it's doing something different.

System:

• AMD Athlon(tm) 64 X2 Dual Core Processor 3800+
• 2GB RAM
• DViCO FusionHDTV DVB-T Dual USB
• Fedora Core 5 (64) with atrpms mythtv:
  • kernel-2.6.17-1.2157_FC5
  • mythtv-0.19-129.rhfc5.at (atrpms - 0.19 r10138)

[lyricnz]

Patch to increase logging in problem area.

[lyricnz]

I added some logging to the place where the error messages are coming from, to try and get a little closer to the problem (see attachment mythtv-logging.patch), then played around starting recordings from the program guide. I got

2006-07-25 02:00:26.990 Reschedule requested for id 68.
2006-07-25 02:00:30.009 Scheduled 13 items in 3.0 = 2.93 match + 0.09 place
2006-07-25 02:00:32.765 Reschedule requested for id 69.
2006-07-25 02:00:35.065 Scheduled 14 items in 2.3 = 2.24 match + 0.06 place
2006-07-25 02:00:36.887 TVRec(1): Changing from None to RecordingOnly
2006-07-25 02:00:38.277 TVRec(1) Error: Set1 channum  input DVBInput
2006-07-25 02:00:39.264 DVB#0 Using DVB card 0, with frontend 'Zarlink MT352 DVB-T'.
2006-07-25 02:00:40.211 TVRec(1) Error: CASE1
2006-07-25 02:00:40.899 TVRec(1) Error: Failed to set channel to . Reverting to kState_None
2006-07-25 02:00:41.423 TVRec(1): Changing from RecordingOnly to None
2006-07-25 02:00:41.877 Finished recording Champ Car World Series: channel 1001
2006-07-25 02:00:42.364 Started recording: Champ Car World Series: channel 1001 on cardid 1, sourceid 1
2006-07-25 02:00:43.657 Reschedule requested for id 0.
2006-07-25 02:00:44.756 Scheduled 14 items in 1.1 = 1.04 match + 0.06 place

This shows that, in TVRec::TuningFrequency?(), request.program is non-null, channum="" and input=DVBInput. My very next attempt to record succeeded:

2006-07-25 02:08:46.547 Reschedule requested for id 70.
2006-07-25 02:08:48.113 Scheduled 23 items in 1.6 = 1.47 match + 0.09 place
2006-07-25 02:08:48.943 TVRec(1): Changing from None to RecordingOnly
2006-07-25 02:08:49.910 TVRec(1) Error: Set1 channum 12 input DVBInput
2006-07-25 02:08:50.756 DVB#0 Using DVB card 0, with frontend 'Zarlink MT352 DVB-T'.
2006-07-25 02:08:51.520 TVRec(1) Error: CASE1
2006-07-25 02:08:52.227 TVRec(1) Error: CASE3
2006-07-25 02:08:52.752 TVRec(1) Error: CASE5
2006-07-25 02:08:53.351 Started recording: Champ Car World Series: channel 1012 on cardid 1, sourceid 1
2006-07-25 02:08:54.169 DVB#0 DVB SI Table Parser Started

It looks like channum was set properly that time. Investigating...

[danielk]

Please test with SVN head, the relevant code has changed considerably.

[anonymous]

Typical mythtv response. Sheesh.