Mythbackend deadlocks after "multiplex is not available"

[Tomi Orava <tomi.orava@…>]

There seems to be some problems in recording realiably with multiple DVB-tuner cards & several virtual tuners that result recordings being done without physical file of any kind. The MythTV version used in the tests has the latest commit of 6dd5e4b821037b20496a7fa715b51fd91a28a49c.

The test setup has 3 DVB Terratec Cinergy 1200 DVB-T pci tuner cards and each of them has usually the max recordings value set to 3. The problem is that its almost daily that I seem to have failed recordings and the interesting thing is that mythbackend doesn't seem to notice that at all ---> ie. no errors are logged about recording failures or such (only tuning about tuning failures). Only later on the web-interface causes the system to notice that although it thinks its still/has been recording something, the file is completely missing.

When the recording fails, this is all I can see from the logs:

2011-02-08 22:38:05.763 PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x201
2011-02-08 22:38:05.764 TVRec(11): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,EITScannerRunning,
2011-02-08 22:38:05.852 PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x294
2011-02-08 22:38:05.886 TVRec(11): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,EITScannerRunning,
2011-02-08 22:38:05.920 TVRec(11): No recorder yet, calling TuningFrequency
2011-02-08 22:38:05.925 DVBChan(11:/dev/dvb/adapter0/frontend0): Opening DVB channel
2011-02-08 22:38:05.927 ChannelBase(11): SelectChannel 8
2011-02-08 22:38:05.930 TVRec(11): Starting Signal Monitor
2011-02-08 22:38:05.930 ChannelThread::run
2011-02-08 22:38:05.960 TVRec(11): SetupSignalMonitor(1, 0)
2011-02-08 22:38:05.996 DVBChan(11:/dev/dvb/adapter0/frontend0): SetChannelByString(8): 
2011-02-08 22:38:06.030 DVBChan(11:/dev/dvb/adapter0/frontend0): Opening DVB channel
2011-02-08 22:38:06.037 DVBSM(/dev/dvb/adapter0/frontend0): Can measure Signal Strength
2011-02-08 22:38:06.041 DVBChan(11:/dev/dvb/adapter0/frontend0) Error: SetChannelByString(8): Multiplex is not available
2011-02-08 22:38:06.053 DVBSM(/dev/dvb/adapter0/frontend0): Can measure S/N
2011-02-08 22:38:06.105 DVBSM(/dev/dvb/adapter0/frontend0): Can measure Bit Error Rate
2011-02-08 22:38:06.134 DVBSM(/dev/dvb/adapter0/frontend0): Can count Uncorrected Blocks
2011-02-08 22:38:06.146 SM(/dev/dvb/adapter0/frontend0)::RemoveFlags: Seen() Match() Wait()
2011-02-08 22:38:06.161 DVBSM(/dev/dvb/adapter0/frontend0): DVBSignalMonitor::ctor initial flags Seen() Match() Wait(Sig,SNR,BER,UB,)
2011-02-08 22:38:06.183 TVRec(11): Signal monitor successfully created
2011-02-08 22:38:06.187 SM(/dev/dvb/adapter0/frontend0)::Start: begin
2011-02-08 22:38:06.199 SignalMonitor: channel change failed
2011-02-08 22:38:06.199 SM(/dev/dvb/adapter0/frontend0)::Start: end
2011-02-08 22:38:06.208 TVRec(11): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,EITScannerRunning,
2011-02-08 22:38:06.211 TVRec(11): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,EITScannerRunning,
2011-02-08 22:38:06.213 TVRec(11): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,EITScannerRunning,
2011-02-08 22:38:06.216 TVRec(11): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,EITScannerRunning,
2011-02-08 22:38:06.252 SignalMonitor: channel change failed
2011-02-08 22:38:06.287 TVRec(11) Error: SignalMonitor failed
2011-02-08 22:38:06.337 TVRec(11): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,EITScannerRunning,
2011-02-08 22:38:06.337 SignalMonitor: channel change failed
2011-02-08 22:38:06.423 TVRec(11): ClearFlags(EITScannerRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2011-02-08 22:38:06.457 TVRec(11): TeardownSignalMonitor() -- begin
2011-02-08 22:38:06.539 DVBSM(/dev/dvb/adapter0/frontend0): Stop() -- begin
2011-02-08 22:38:06.580 SM(/dev/dvb/adapter0/frontend0)::Stop: begin
2011-02-08 22:38:06.488 SignalMonitor: channel change failed
2011-02-08 22:38:06.751 SM(/dev/dvb/adapter0/frontend0)::Stop: end
2011-02-08 22:38:06.754 DVBSM(/dev/dvb/adapter0/frontend0): Stop() -- end
2011-02-08 22:38:06.756 SM(/dev/dvb/adapter0/frontend0)::Stop: begin
2011-02-08 22:38:06.760 SM(/dev/dvb/adapter0/frontend0)::Stop: end

It's not a hardware problem as the hang does happen to any of the three installed cards during a longer periods. I've also just seen the exactly same problem in my parents setup which has the latest 0.23-fixes version installed (only 2 DVB tuner cards). Somehow I get the feeling this problem might be related to the #6719.

[Tomi Orava <tomi.orava@…>]

Full gdb backtrace after the 'Multiplex is not available' error has occurred.

[Tomi Orava <tomi.orava@…>]

Mythbackend log with verbose parameters: -v important,general,record,eit,channelscan,channel --noupnp

[Tomi Orava <tomi.orava@…>]

Update: Based on a days worth of testing, I think I might actually have two different problems in these two systems.

1) I haven't seen any of the "Multiplex is not available" errors and/or DVB-tuner hangs after I made sure to reset to zero all the channel-tables 'useonairguide' values on encrypted channels (I don't have dvbcam installed ---> only free to air channels can be watched with these systems).

2) I still seem to get missing recordings ie. metadata exists but no file seems to get opened ever, even though the backend thinks it really is recording something. This I have to try digg some more ...

[sphery]

Based on ​http://www.gossamer-threads.com/lists/mythtv/dev/471696#471696 , it sounds like disabling useonairguide on encrypted channels that Tomi doesn't have access to fixed one of the problems causing the capture card to get into an invalid/broken state. This is mostly a misconfiguration, but it might be nice to detect when we can't decrypt channels and not use them for EIT.

It also sounds like with only one card configured to do active EIT collection, he didn't see a failure. I couldn't tell whether this was due to problems with the driver/card or if it's actually just a duplicate of #8251 (where multirec inputgroups are ignored--which may not show up with only one card configured to do active EIT collection, depending on which card was doing EIT). I'm thinking it's a dup of #8251.

[mythtv@…]

I would like to suggest an alternate cause of this issue: a race condition when attempting to simultaneously tune two tuners in one device. I have had similar issues over the past few months. Seeing this ticket, I disabled EIT by deselecting useonairguide for all my channels. I then tested by recording multiple programs with the same start time. One program didn't record, and MythTV had attempted to record it via a dual-tuner device.

Next, I tested by setting multiple items to record, but setting the "Start Early" fields to make sure the start times weren't exactly the same. I only separated by a minute. This worked correctly. I also had a case where two MythTV attempted to tune two programs simultaneously, but using different devices. This also worked correctly.

So, I suspect there is a race condition, either in the device (HD HomeRun? with two tuners) or in MythTV. Would anyone with a different device with multiple tuners be able to try this experiment? That might narrow it down to my device or MythTV.

I'm uploading a log for my recordings, along with version information. In the log, the first failure is Bones on April 7, right at the beginning of the log. Then on 4/11, after turning off EIT, I tried recording several shows at 1900. TMZ failed. I did more tests at 2100, just recording 5 minutes at a time. However, since one program was already recording on the dual tuner, the other two streams were split between devices. Finally, at 2330, I started recording TMZ again. At 2334 (2335 - Start Early==1), I started recording Letterman. At 2335 (Start Early == 0) I started recording Leno. All three recorded correctly.

Full disclosure: I am a newbie to posting & fairly new to MythTV, so my apologies if I've made a mistake here. Also, my sample size is small. If you like, I can spend some time over the next few evenings to try this more. However, all the failed recordings in the previous months occurred when I had multiple programs with the same start time. I haven't scanned the logs to see if they were being sent to the same device though.

Hardware:
First device: HD HomeRun?, single tuner.
Second device: HD HomeRun?, dual tuner.
Input: Terrestrial antenna.

[Matt Dorsch <mythtv@…>]

Testing for race condition in simultaneous tuning.

[Matt Dorsch <mythtv@…>]

Version information.

[Matt Dorsch <mythtv@…>]

My apologies. I was running into issue 9247. Please ignore the above.

[danielk]

Fairly certain this was fixed in master by [9b22460f53].