Guide data/Manual Recording issue with padding less than show length

[graywolfusmc]

Not positive this is just my setup or an issue with V9.2.6.976 but do not have this issue with V9.2.1.826 Reference: https://forums.sagetv.com/forums/showthread.php?t=67158 Steps to recreate issue: Find 3x 1 hr shows back to back on same channel Manual record the second show starting 1 min later and ending 1 min early Manual record the first show starting 1 min early and ending 1 min later Manual record the third show starting 1 min early and ending 1 min later

All looked well until it was time for the second show to record. The Guide then had blank for the 2nd show (could not even get focus there) and the first show just continued recording but looks like end time was null.

Saw the following in the logs: Fri 3/17 21:01:00.824 [Scheduler@1cabdc1] Removing from schedule cause expired FA[stationID=16374 Tucker Carlson Tonight time=Fri 3/17 20:00:00.000 dur=1:01:00] Fri 3/17 21:01:02.121 [Timer-4@10e6617] Added:ManualRecord[A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V] time=Fri 3/17 20:00:00.000 dur=1:01:00] Fri 3/17 21:01:02.121 [Timer-4@10e6617] Modified EPG data linkage for existing manual record: ManualRecord[A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V] time=Fri 3/17 20:00:00.000 dur=1:01:00] overlapAir=A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V] Fri 3/17 21:01:02.122 [Timer-4@10e6617] Updating metadata w/ new Airing for existing recording from: MediaFile[id=65203316 A[65123791,65123718,"Tucker Carlson Tonight",16374@0317.20:00,60,T] mask=TV host=HTPC-BR encodedBy=Hauppauge WinTV 418 Video Capture DVD Standard Play format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 29.97 fps 720x480 4:3 6400 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]{SeriesInfoID=2551749, DefaultBackground=null}] C:\SageTV32bit\SageTV\Video\TuckerCarlsonTonight-65123791-0.mpg, Seg0[Fri 3/17 20:00:00.001-Fri 3/17 21:01:00.001]] to be A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V] Fri 3/17 21:01:04.671 [Seeker@1dc1ac1] Enforcing keep at most limits for the files... Fri 3/17 21:01:04.677 [Scheduler@1cabdc1] # Airs=9708

[Narflex]

I doubt a bug like this would have crept in during that time period. My first guess would be that the EPG data for this program was getting updated close in time to when the recording was occurring...and the re-creation of the linked manual records was causing some issue.

Easiest thing to try to fix this is to set repair_epg_manual_record_mismatches=false in the Sage.properties file. Then the logic from what you see in the logs won't get executed (that logic was never bulletproof...but was supposed to help some types of schedule changes that can occur).

[graywolfusmc]

Thanks I'll set repair_epg_manual_record_mismatches=false FYI this did happen multiple times during the week I had V9.2.6.976 running but do not see the issue with V9.2.1 which I have on other SageTV Servers.

[Narflex]

Yeah, I'd need to see a complete log file from when it had the issue to determine if it had to do with correlation in time to an EPG update or if it's something else I'm not aware of.

[graywolfusmc]

here is the log file sagetv_7.zip

[Narflex]

It doesn't appear like there was an EPG update during this time...which is very odd because that's what generally triggers that path for updating the ManualRecord like that. So then I think the most likely culprit is a plugin that's causing it...but I'd have no idea what that would be.

[wnjj]

The only thing I could see with a quick review that could possibly even be related is this change: https://github.com/google/sagetv/commit/620916f07cd0fd4e50b774ac944f2ce8e74f5771

It involves fast mux switching when transcoding. Graywolf, are you transcoding with your setup?

[Narflex]

Let me explain what some of those logs mean.

This first one is when the Scheduler detects it is past the end of it's program (i.e. expired), which is correct since this one ended at 21:01. Fri 3/17 21:01:00.824 [Scheduler@1cabdc1] Removing from schedule cause expired FA[stationID=16374 Tucker Carlson Tonight time=Fri 3/17 20:00:00.000 dur=1:01:00]

This is the database indicating a new ManualRecord was added (can happen from a lot of callsites). Fri 3/17 21:01:02.121 [Timer-4@10e6617] Added:ManualRecord[A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V] time=Fri 3/17 20:00:00.000 dur=1:01:00]

This is a very unique entry. This is when AddAiring in the database is invoked and that new Airing will modify the start/stop times of a program (which causes existing Airing objects that overlap w/ it to be removed..the database will not allow overlapping Airing on a Channel). It then deletes existing ManualRecords attached to that Airing and recreates them attached to the new Airing. Fri 3/17 21:01:02.121 [Timer-4@10e6617] Modified EPG data linkage for existing manual record: ManualRecord[A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V] time=Fri 3/17 20:00:00.000 dur=1:01:00] overlapAir=A[65203366,65203365,"Tucker Carlson Tonight",16374@0317.20:00,61,T V]

So this would only occur if something called AddAiring for the program "Tucker Carlson Tonight" with a 61 minute duration at 8pm. There's only 3 ways that AddAiring can get invoked.

1. EPG updates (but your log shows no CPU usage on the EPG thread during the error, so this can be ruled out)
2. MediaFile imports; but these never attach themselves to Channel objects unless they are linking to an already existing Airing, and this one has a Channel.
3. The SageTV API call for AddAiring which is never used by SageTV's STV...but is used by various plugins/extensions.

Because of that..my guess is #3, which means I don't know anything about that code. :)

This is also running on a Thread called "Timer-X"..which I know I'd never use a Timer in SageTV for something like this...but it's something that would definitely happen in a plugin in order to update some information in the database at a specific time (like when a recording ended).

I know you went to a different version and had the problem...went back and it went away...but I'm guessing it was just coincidence with it occurring.

ALSO, PLEASE DON'T SET repair_epg_manual_record_mismatches=false...as after I've looked at the code more that means it'll just delete ManualRecords when Airings change...which will DEFINITELY reduce the WAF.

[graywolfusmc]

Thanks for additional information and I have reverted to repair_epg_manual_record_mismatches=true

[graywolfusmc]

The only thing I could see with a quick review that could possibly even be related is this change: 620916f

It involves fast mux switching when transcoding. Graywolf, are you transcoding with your setup?

No transcoding.

[graywolfusmc]

Based upon Narflex's comments. I will close this as it is probably another plug-in causing the issue