Rare duplicate recordings with manual recording rules

[ulmus-scott]

• Platform:
  Xubuntu 23.10 Linux htpc-HP 6.5.0-35-generic #35-Ubuntu SMP PREEMPT_DYNAMIC Fri Apr 26 11:23:57 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
• MythTV version:
  fixes/33
• Package version:
  v33.0+fixes.20230210.026e506-0ubuntu0
• Component:
  backend?

What steps will reproduce the bug?

Set up a manual recording rule in mythfrontend. Rarely, there will be two recordings from that rule.

How often does it reproduce? Is there a required condition?

Rarely. No known requirements.

What is the expected behaviour?

Only one recording is made per manual recording rule.

What do you see instead?

The expected recording with the entered title with " (Manual Record)" appended as the title and description.

A second recording that is identical except the title and description are different. I assume they match the broadcast EIT data for that time. (No " (Manual Record)" in the title and the description is a few sentences.)

Additional information

This has been occurring rarely for many years.

We set our recordings to start 2 minutes early and end 2 minutes late and the duplicate recording always has the correct title and description for the normal recording time.

We have never seen the duplicate recording in mythfrontend -> Manage Recordings -> Upcoming Recordings, but we don't check there very often.

[gigem]

What is the recording rule ID for the manual rule and what are the recording rule IDs for the two recordings? Also, can you please upload the backend log for the time in question?

[ulmus-scott]

We already deleted the duplicate recording. From what I can tell in mythfrontend, the recording rule ID for the recording is 1752. I don't know how to find the recording rule ID for the rule itself.

However, looking at the log mythbackend.log.gz the recording rule ID does appear to be 1752 for both recordings.

The titles are "GP Rodgers & Hammerstein (Manual Record)" and "Great Performances". It appears the recording rule was set up on 2024-05-26T17:47:03.294738-04:00. The recording was on 2024-05-31 from 20:58 to 23:02, and the duplicate deleted 2024-06-01T19:53.

2024-05-31T20:58:00.231749-04:00 htpc-HP mythbackend: mythbackend[1321]: I Scheduler scheduler.cpp:2904 (HandleRecordingStatusChange) Tuning recording: "Great Performances": channel 12601 on cardid [1], sourceid 1
2024-05-31T20:58:00.231986-04:00 htpc-HP mythbackend: mythbackend[1321]: E Scheduler recordinginfo.cpp:1117 (InsertProgram) RecordingInfo::InsertProgram(ProgramInfo(12601_20240601005800.ts): channame(WETA-HD)#012             startts(Sat Jun 1 01:00:00 2024 GMT) endts(Sat Jun 1 03:00:00 2024 GMT)#012             recstartts(Sat Jun 1 00:58:00 2024 GMT) recendts(Sat Jun 1 03:02:00 2024 GMT)#012             title(GP  Rodgers & Hammerstein (Manual Record))): recording already exists...

Similar log for a duplicated NOVA (rule 1743) on 2024-05-15T20:58.

[gigem]

Thanks. Can you also please dump the guide data from the program table in the database for the channel in question around the time of the recording. Since you said you're using EIT, I want to see what's actually there to cause an unexpected match.

[ulmus-scott]

I'm not sure what exactly you want by "dump the guide data from the program table in the database for the channel in question around the time of the recording". I don't know mysql but I determined 'SELECT * FROM program WHERE chanid = 12601' but I don't know how to get that into a file. Regardless, the database backup is only about 70 MiB, so I could upload that if it is easier?

I just triggered it on my development system while testing #646 rebased onto master:

2024-06-03 16:46:07.826844 I  Reschedule requested for MATCH 1204 0 0 - SaveRule test (Manual Record)
2024-06-03 16:46:07.911267 I  Scheduled 4 items in 0.0 = 0.01 match + 0.00 check + 0.01 place
2024-06-03 16:46:07.929874 I  TVRec[5]: Changing from None to RecordingOnly
2024-06-03 16:46:07.930412 I  TVRec[5]: TuningFrequency(Program(ProgramInfo(12601_20240603204600.ts): channame(WETA-HD)
             startts(Mon Jun 3 20:00:00 2024 GMT) endts(Mon Jun 3 21:00:00 2024 GMT)
             recstartts(Mon Jun 3 20:46:00 2024 GMT) recendts(Mon Jun 3 21:00:00 2024 GMT)
             title(test (Manual Record))) channel(26_1) input(None) flags(Recording,))
2024-06-03 16:46:07.930436 I  TVRec[9]: ASK_RECORDING 9 0 0 0
2024-06-03 16:46:07.946737 I  HDHRSH[5](10414922): Added 2 devices from 10414922
2024-06-03 16:46:07.984980 I  HDHRSH[5](10414922): Connected to device(10414922-1)
2024-06-03 16:46:08.106107 I  Tuning recording: "test (Manual Record)": channel 12601 on cardid [5], sourceid 1
2024-06-03 16:46:08.699020 I  Updating status for "test (Manual Record)" on cardid [5] (Tuning => Recording)
2024-06-03 16:46:08.768436 I  TVRec[5]: rec->GetPathname(): '/media/data/htpc/Recordings/recordings/12601_20240603204600.ts'
2024-06-03 16:46:08.768753 I  TVRec[5]: TuningNewRecorder - CreateRecorder()
2024-06-03 16:46:08.820498 I  TVRec[10]: ASK_RECORDING 10 0 0 0
2024-06-03 16:46:09.245493 I  Reschedule requested for MATCH 0 1 25 2024-06-03T20:30:00Z EITScanner
2024-06-03 16:46:09.341268 I  Scheduled 4 items in 0.1 = 0.05 match + 0.00 check + 0.00 place
2024-06-03 16:46:28.816341 I  Reschedule requested for MATCH 1205 0 0 - SaveRule 26_2 WETA UK - 16:00 (Manual Record)
2024-06-03 16:46:28.895268 I  Scheduled 5 items in 0.0 = 0.01 match + 0.00 check + 0.01 place
2024-06-03 16:46:28.921835 I  TVRec[9]: Changing from None to RecordingOnly
2024-06-03 16:46:28.922523 I  TVRec[9]: TuningFrequency(Program(ProgramInfo(12602_20240603204600.ts): channame(WETA UK)
             startts(Mon Jun 3 20:00:00 2024 GMT) endts(Mon Jun 3 21:00:00 2024 GMT)
             recstartts(Mon Jun 3 20:46:00 2024 GMT) recendts(Mon Jun 3 21:00:00 2024 GMT)
             title(26_2 WETA UK - 16:00 (Manual Record))) channel(26_2) input(None) flags(Recording,))
2024-06-03 16:46:28.941222 I  Tuning recording: "26_2 WETA UK - 16:00 (Manual Record)": channel 12602 on cardid [9], sourceid 1
2024-06-03 16:46:28.942185 I  TVRec[10]: ASK_RECORDING 10 0 0 0
2024-06-03 16:46:28.943991 E  RecordingInfo::InsertProgram(ProgramInfo(12602_20240603204600.ts): channame(WETA UK)
             startts(Mon Jun 3 20:00:00 2024 GMT) endts(Mon Jun 3 21:00:00 2024 GMT)
             recstartts(Mon Jun 3 20:46:00 2024 GMT) recendts(Mon Jun 3 21:00:00 2024 GMT)
             title(The Real Crown: Inside the House of Windsor)): recording already exists...
2024-06-03 16:46:28.947362 I  TVRec[10]: Changing from None to RecordingOnly
2024-06-03 16:46:28.947561 I  TVRec[10]: TuningFrequency(Program(ProgramInfo(12602_20240603204601.ts): channame(WETA UK)
             startts(Mon Jun 3 20:00:00 2024 GMT) endts(Mon Jun 3 21:00:00 2024 GMT)
             recstartts(Mon Jun 3 20:46:01 2024 GMT) recendts(Mon Jun 3 21:00:00 2024 GMT)
             title(The Real Crown: Inside the House of Windsor)) channel(26_2) input(None) flags(Recording,))
2024-06-03 16:46:28.957766 I  Tuning recording: "The Real Crown: Inside the House of Windsor": channel 12602 on cardid [10], sourceid 1
2024-06-03 16:46:29.484653 I  Updating status for "The Real Crown: Inside the House of Windsor" on cardid [10] (Tuning => Recording)
2024-06-03 16:46:29.522484 I  Updating status for "26_2 WETA UK - 16:00 (Manual Record)" on cardid [9] (Tuning => Recording)
2024-06-03 16:46:29.544014 I  TVRec[10]: rec->GetPathname(): '/media/data/htpc/Recordings/recordings/12602_20240603204601.ts'
2024-06-03 16:46:29.544402 I  TVRec[10]: TuningNewRecorder - CreateRecorder()
2024-06-03 16:46:29.576632 I  TVRec[9]: rec->GetPathname(): '/media/data/htpc/Recordings/recordings/12602_20240603204600.ts'
2024-06-03 16:46:29.576754 I  TVRec[9]: TuningNewRecorder - CreateRecorder()
2024-06-03 16:46:29.578045 I  TVRec[9]: ASK_RECORDING 9 0 0 0
2024-06-03 16:46:29.812480 I  TVRec[5]: ASK_RECORDING 5 0 0 0
2024-06-03 16:46:29.812553 I  TVRec[5]: ASK_RECORDING 5 0 0 0
2024-06-03 16:46:39.292731 I  JobQueue: Metadata Lookup Starting for "test (Manual Record)" recorded from channel 12601 at 2024-06-03T20:46:00Z
2024-06-03 16:46:40.797057 E  JobQueue: Metadata Lookup Errored: "test (Manual Record)" recorded from channel 12601 at 2024-06-03T20:46:00Z (Failed with Exit Status 128)
2024-06-03 16:46:44.301152 I  JobQueue: Metadata Lookup Starting for "26_2 WETA UK - 16:00 (Manual Record)" recorded from channel 12602 at 2024-06-03T20:46:00Z
2024-06-03 16:46:45.807623 E  JobQueue: Metadata Lookup Errored: "26_2 WETA UK - 16:00 (Manual Record)" recorded from channel 12602 at 2024-06-03T20:46:00Z (Failed with Exit Status 128)
2024-06-03 16:46:49.312905 I  JobQueue: Metadata Lookup Starting for "The Real Crown: Inside the House of Windsor" recorded from channel 12602 at 2024-06-03T20:46:01Z
2024-06-03 16:46:50.816769 E  JobQueue: Metadata Lookup Errored: "The Real Crown: Inside the House of Windsor" recorded from channel 12602 at 2024-06-03T20:46:01Z (Failed with Exit Status 128)

"The Real Crown: Inside the House of Windsor" shows recording rule: 1202, "The Real Crown: Inside the House of Windsor"
"26_2 WETA UK - 16:00 (Manual Record)" shows recording rule: 1205, "26_2 WETA UK - 16:00 (Manual Record)"

[gigem]

The easiest way to get the query output is to redirect the output from the mysql command to a file. For example:

echo ' select count(*) from recorded' | mysql -h <host> -u mythtv mythconverg | tee output.txt

Next easiest, IMHO, is to use the mycli client (https://github.com/dbcli/mycli). For example:

MariaDB mythtv@host:mythconverg> \once output.txt
MariaDB mythtv@host:mythconverg> select count(*) from recorded

I use manual recordings occasionally (as recently as a few weeks ago) and have never seen anything like this. I'll retest tomorrow to be sure.

[ulmus-scott]

program_table-dev.tsv.txt
program_table.tsv.txt

It looks like on my dev machine it took the manualid from a deleted recording rule, but on my other machine I see no evidence of this.

[gigem]

Thanks for the program table data. It looks normal. Do you have regular, recording rules which match programs at the same time/channel as your manual rules?

[ulmus-scott]

Thanks for the program table data. It looks normal. Do you have regular, recording rules which match programs at the same time/channel as your manual rules?

We only use manual recording rules since the broadcast EIT data in the US is poor (some channels appear to not transmit anything) and anything we want to record is either at the same time every week or we only want a single episode (e.g. we are not necessarily interested in every episode of "Great Performances"). Also, the EIT data does not appear to include a subtitle.

We don't record very much, so setting up the manual recording rules works for us. Also, it allows us to force the recording to start early and end late.

[gigem]

How you record is your business. Though, I must say the Schedules Direct, guide data is accurate, useful and very affordable. I don't get any money from them but the more subscribers they have, the easier it is for them to keep the service available and affordable.

Anyway, something is causing programs in the guide data you have to match. Manual recording rules should not do that and don't in my testing. I will have to add some more information to the log messages in hopes of shedding some light on the problem. I'll try to do that in the next day or two.

[gigem]

I apologize for taking so long to get back to you. Other things keep getting in the way and now I have something weird going on that makes every MythTV program to pause for several minutes at start up. Anyway, I realized that most of what I need to know for now can be found by a simple patch and increasing the log level. Please apply the patch below and then change your backend logging to use --loglevel debug and --verbose schedule.

diff --git a/mythtv/programs/mythbackend/scheduler.cpp b/mythtv/programs/mythbackend/scheduler.cpp
index 5570c8a16a..13ae284d7f 100644
--- a/mythtv/programs/mythbackend/scheduler.cpp
+++ b/mythtv/programs/mythbackend/scheduler.cpp
@@ -643,6 +643,8 @@ void Scheduler::PrintRec(const RecordingInfo *p, const QString &prefix)
     if (p->GetRecordingPriority2())
         outstr += QString("/%1").arg(p->GetRecordingPriority2());
 
+    outstr += QString(" (id=%1)").arg(p->GetRecordingRuleID());
+
     LOG(VB_SCHEDULE, LOG_INFO, outstr);
 }

[ulmus-scott]

I didn't have time to test with your logging patch on my development machine, but I did increase the logging on my production machine (which uses Ubuntu's package for v34).

Search for "Disco": mythbackend.log.2.gz
The "Music Disco (Manual Record)" recording had already started when a reschedule was requested and "Disco: Soundtrack of a Revolution" appears (the last three characters are truncated in some places in the log).

[gigem]

This latest log is helpful but not helpful enough to confirm what I think might be happening. To be sure, I really need to know the matched recordid. Please apply the patch above at your convenience and upload the resulting log the next time the issue occurs.

[ulmus-scott]

With the patch applied to master:

Around 01:00 in the log:
mythbackend.20240716043105.39348.log

1. Reschedule with titles as entered
2. Add new recording rule 1251, reschedule with titles and durations (see rule id 1249) from program guide for other rules (and I saw those different titles briefly in mythfrontend)
3. New recording with title from program guide starts
4. Soon after another reschedule resets the titles and durations back to the entered values

Similar behavior when I deleted rule 1251 around 01:34. Perhaps it's relevant that rule 1251 is a weekly recording rule?

[gigem]

I haven't forgotten about this problem. Besides trying to watch as much Olympics as I can, I've been dealing with a mediacl issue that often makes working on the computer painful.

Anyway, my fear was that the EIT code was overwriting the artificial, manual programs in the program table. I just checked and I don't see how that can happen. I need to check another code path or two to look for errors.

Besides the manual recording rule, what other rules are you careating at the same time? They might be interacting with the manual rule/programs in an unexpteted way.

[ulmus-scott]

We only use manual recordings (single or weekly). The only other rules would be whatever MythTV create automatically for EIT scanning. (We rarely use live TV but I don't think it is relevant to this issue.)

Console log from a different branch without your extra logging:
mythbackend.20240805013735.log
I triggered it using only single recording this time, so I don't think the type of manual recording matters. (I had also tried unsuccessfully to trigger this with a mix of single, daily, and weekly manual recording rules just prior.)

For future reference use mythbackend --loglevel=debug -v schedule --logpath=/tmp