17,000 Recording will not commence until a PMT is set messages, no recording.

[Bill Meek <keemllib@…>]

If the "Recording will not commence until a PMT is set messages, no recording" starts printing, recordings are not made. In my most recent case, my test backend failed, but my production host recorded the same show just fine.

I also was able to stop the failed recording and it restarted (mid show) and it recorded just fine.

At least three other people on the -users list and one other on IRC (I don't remember which channel) have mentioned this.

www.gossamer-threads.com/lists/mythtv/users/534924

[Bill Meek <keemllig@…>]

Full version output of v0.27-pre2-456-g16c178d and backend log.

[bpreston67@…]

I am experiencing the same issue with HD-3000 cards, 2 of them. Often, one will record and the other will fail with this error being reported. In my case it always seem to be the same adapter failing, /adapter0/frontend0 - swapping the cards around does not seem to matter. I've also exchanged cards in an attempt to address the problem (thinking it might be hardware related, I have 3 of these, run 2 in my backend)

[linuxdreas@…]

Another tidbit of information: It's always the second recording that's failing, independant of the hardware. For example: a show is recording from 14:00 to 15:00 on adapter 1. Another show at 14:30 on adapter 2 will fail to record. A recording at 15:05 on adapter 2 will be successful.

[jpoet]

That last comment gave me an idea. I am attaching a patch which might fix the problem.

I should warn, that my system is currently recording, so I have not tested this patch at all, but it does compile against latest 0.27-pre.

[jpoet]

Make sure the first things in the file are a PAT & PMT

[Bill Meek <keemllib@…>]

Replying to jpoet:

Running on: v0.27-pre2-529-g38af2c7-dirty (with the above patch.) I had two good recordings this morning. They were scheduled one hours shows one at 9:00 and one at 10:00. No problems.

Using the EPG, I just sheduled a single show and the no PMT failures started as before. And since that failed, I tried again with another show, this time with the --setverbose record added. Annotated log file attached. Line 8474 may be of interest.

I tried a third time, thinking that I'd found a reliable way to duplicate the problem, but the show recorded normally.

I have had one case of back to back shows that failed (last week.) It is not the norm for me.

[Bill Meek <keemllib@…>]

2nd failure in the file has --setverbose record added

[Ken Emerson <kenneth.emerson@…>]

I applied the attached patch (StartNewFile?) and it did not correct the problem. Same symptoms.

[jpoet]

If anyone can figure out what exactly it takes to trigger the problem, that would help greatly. I setup 80 manual records and was only able to trigger the problem once.

[bpreston67@…]

I don't know how helpful this will be but I will share my observations over the past couple of days.

I've started running mythbacked in a terminal so I may better observe conditions in real time. I had 2 failures over the past couple of days. When exiting mythbackend to restart it (which normally corrects the problem temporarily), the first failure generated a list of several threads that failed to exit properly.

The second failure generated the following error and the backend exited with a segmentation fault:

(process:27871): GLib-ERROR : Creating pipes for GWakeup: Too many open files

In the case of the second failure, I had been watching live TV and changing channels frequently until about 30 minutes prior to the recording start attempt that generated this error. I may well have been doing the same thing prior to the first failure that resulted in several threads that could not exit properly.

In all cases, my PMT errors seem to occur in the evening when attempting to record HD content on both HD-3000 tuners. As noted by another above, it does seem to always be the second tuner initialization process that tends to fail, at least as long as I've been paying attention to this nuance.

Hopefully this is helpful and does not confuse matters further.

[Ken Emerson <kenneth.emerson@…>]

John P: My results are similar to yours, perhaps a little more frequently. I cannot seem to identify any particular set of circumstances that trigger the failure. I have scheduled additional recordings (to throw away) over the past several days. Of the approximately 40 recordings, there were only three failures. The most recent occurred this AM on a normally scheduled recording. It was by itself with no previous or subsequent recording activity. Currently running v0.27-pre2-535-gfd3d2c1-dirty (dirty because of the patch applied from this ticket).

Is there a particular set of logging flags that might shed some light on this problem? Currently I'm running with whatever the default logging is set to. Today, all that I got was:

2013-01-18 05:59:30.184437 I [3403/3946] TVRecEvent tv_rec.cpp:1557 (HandlePendingRecordings?) - TVRec(1): ASK_RECORDING 1 13 0 0

2013-01-18 05:59:58.077819 I [3403/3946] TVRecEvent tv_rec.cpp:1043 (HandleStateChange?) - TVRec(1): Changing from None to RecordingOnly?

2013-01-18 05:59:58.077889 I [3403/3946] TVRecEvent mythdbcon.cpp:409 (PurgeIdleConnections?) - New DB connection, total: 24

2013-01-18 05:59:58.079748 I [3403/3946] TVRecEvent tv_rec.cpp:3583 (TuningCheckForHWChange) - TVRec(1): HW Tuner: 1->1

2013-01-18 05:59:58.174458 N [3403/3984] Scheduler autoexpire.cpp:264 (CalcParams?) - AutoExpire?: CalcParams?(): Max required Free Space: 7.0 GB w/freq: 14 min

2013-01-18 05:59:58.181381 I [3403/3984] Scheduler scheduler.cpp:2607 (HandleRecordingStatusChange?) - Tuning recording: "QC Today at 6A": channel 1061 on cardid 1, sourceid 1

2013-01-18 05:59:58.902005 I [3403/3403] CoreContext? scheduler.cpp:652 (UpdateRecStatus?) - Updating status for "QC Today at 6A" on cardid 1 (Tuning => Recording)

2013-01-18 05:59:58.966179 I [3403/3946] TVRecEvent tv_rec.cpp:4077 (TuningNewRecorder?) - TVRec(1): rec->GetPathname?(): '/mythtv/data/1061_20130118120000.mpg'

2013-01-18 05:59:58.966976 E [3403/3946] TVRecEvent recorders/recorderbase.cpp:206 (SetStrOption?) - RecBase?(1:103914CF-0): SetStrOption?(...recordingtype): Option not in profile.

2013-01-18 05:59:59.132458 W [3403/11325] RecThread? recorders/hdhrrecorder.cpp:104 (run) - HDHRRec(1): Recording will not commence until a PMT is set.

2013-01-18 05:59:59.237625 W [3403/11325] RecThread? recorders/hdhrrecorder.cpp:104 (run) - HDHRRec(1): Recording will not commence until a PMT is set.

[jpoet]

Most of the time we have processed a PAT *before* DTVSignalMonitor::SetProgramNumber?() is called. However, once in a while, SetProgramNumber?() is called before we have seen a PAT, and when that happens we end up resetting the "program number" to -1, so when we finally do see the PAT we no longer can match it.

It is possible that e75fb21c45942ee8a17a8d5c64901f2868658440 is to blame for the change in behaviour.

[jpoet]

Extra debugging statements added to log

[danielk]

Possible fix

[danielk]

Looking at John's log it appears the problem is the ResetMPEG(3) called at the end of MPEGStreamData::SetDesiredProgram?(3) because the pid is not found for program 3 in the PAT. Probably because the requisite PAT section hasn't been seen yet. Before [e75fb21c4] was applied calling ResetMPEG() had no effect on the ATSC major and minor channels, it only reset the program number. After [e75fb21c4] the ATSC parts of the class are reset in addition to the program number. We find the program ok after this, but later on we call ATSCStreamDate::SetDesiredChannel?() which calls Reset(-1) because it can't find the channel with major/minor -1/-1 ...

The attached patch reworks the ResetMPEG() in ATSCStreamData and DVBStreamData to work more like they did in MythTV 0.26, except we do actually reset the higher level caches.

[jpoet]

Log of failure with v1 patch applied

[Ken Emerson <kenneth.emerson@…>]

Daniel: I applied your patch (11334-v1.patch) early this morning and then scheduled 17 recordings. Unfortunately there were two failures (Recording will not commence until a PMT is set). :-(

If it matters, I changed the two files in the patch and only did a make since I had done a git pull and make clean only 6 hours previously.

-- Ken E.

[Daniel Thor Kristjansson <danielk@…>]

In 96de301144ce2362e26dbbe10d85745155c0bab8/mythtv:

Revert "Resolve MPEGStreamData::Reset() ambiguities."

This reverts commit [e75fb21c45942ee8a17a8d5c64901f2868658440].

This is causing tuning to fail some of the time.

What appears to happen is that MPEGStreamData::SetDesiredProgram?()
calls ResetMPEG() when a program number is desired which has not
been seen yet. This cause the ATSC tuning data to also be reset,
which wasn't the case before [e75fb21c45] because of a bug in the
implementation, and this causes tuning to fail.

Refs #11334.

[Bill Meek <keemllib@…>]

Replying to Daniel Thor Kristjansson <danielk@…>

Update:

With 96de301 applied, I have had no failures in the last 100 recordings. In the 100 recordings before the change, there were 7 failures.

[Ken Emerson <kenneth.emerson@…>]

While not the author of this ticket, I was one of the original reporters of this problem. I also can report that I have not observed any of these failures since upgrading. Would think you could close this ticket. And thanks you for the resolution.

[bpreston67@…]

I cannot provide my recording count, but I have had no failures in about a week. This looks like it's been corrected to me.

[danielk]

Thanks for the feedback.

It isn't appropriate to close this yet as I just reverted the problematic commit, so the problems that motivated the original commit have been reintroduced. But knowing this commit was indeed the problem is very valuable and allows me to try at a proper fix without having master in a bad state.

[Boleslaw Ciesielski <bc-mythtv@…>]

piece of the log file trying to record "Reign" at 2013-10-17 21:00 EDT

[Boleslaw Ciesielski <bc-mythtv@…>]

I am still seeing this problem about once a week with 0.27-41.git.1224f05 (on Fedora 18). Attached is the relevant piece of the backend log with --verbose general,channel,record,siparser

The recording in question is "Reign" at 2013-10-17 21:00 EDT on channel 56-1 WLVIDT. The tuner seems to be stuck on 7-1 WHDHDT.

I have 3 OTA tuners. The error seems to happen randomly on any tuner or any channel. Please let me know if I can provide any more information.

[Karl Egly]

Remove the milestone as per comment:16. This issue has been fixed by reverting an earlier change.

[Klaas de Waal]

As this problem is reported to be fixed the ticket can be closed.