VerifyLoad issue?

[Space]

Gary,

Today I've noticed in the EPG123 log something unusual... This may be a bug with LoadMXF and not EPG123, but I thought I'd post it here in case you wanted to investigate...

I will include the (what I believe to be) significant log entries below, but if you want to see more, let me know...

Yesterday, the MXF was created and loaded without issue, it included a bunch of VerifyLoad changes, but I will include only the ones for DISNHD:

Code: Select all

[1/24/2021 7:38:51 PM] Entering ImportMxfFile() for file "c:\programdata\garyan2\epg123\output\epg123.mxf".
[1/24/2021 7:43:28 PM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[1/24/2021 7:43:28 PM] Exiting ImportMxfFile(). SUCCESS.
...
[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD at 2/5/2021 8:30:00 AM: Changing end time of [EP02647450_0231 - [Puppy Dog Pals]-[s03e07 Valentine's Day Mix-Up; A Stinky Story]] from 2/5/2021 9:00:00 AM to 2/5/2021 8:55:00 AM
[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD: Adding schedule entry from 2/5/2021 9:00:00 AM to 2/5/2021 9:30:00 AM for program [EP03227430_0038 - [T.O.T.S.] - [s01e19 The Fly-Along; Rock-A-Bye Birdie]].
[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD at 2/5/2021 10:30:00 PM: Changing end time of [EP02200570_0099 - [Bunk'd]-[s05e04 Tentacle Difficulties]] from 2/5/2021 11:00:00 PM to 2/5/2021 10:55:00 PM
[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD: Adding schedule entry from 2/5/2021 11:25:00 PM to 2/5/2021 11:55:00 PM for program [EP03025522_0004 - [Gabby Duran & the Unsittables] - [s01e04 Crushin' It]].
[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD: Removing schedule entry on 2/5/2021 11:30:00 PM for [EP03025522_0004 - [Gabby Duran & the Unsittables]-[s01e04 Crushin' It]] due to being replaced/overlapped by another schedule entry.

Then, today, for some reason, the connection to Schedules Direct failed (a rare occurrence) which meant the MXF file was not created and therefore the old MXF file was left alone.

Code: Select all

[1/25/2021 7:38:00 PM] [ INFO] Beginning EPG123 update execution. 2021-01-26 00:38:00Z
[1/25/2021 7:38:00 PM] [ INFO] DaysToDownload: 21 , TheTVDBNumbers : True , PrefixEpisodeTitle: True , PrefixEpisodeDescription : False , AppendEpisodeDesc: False , OADOverride : True , TMDbCoverArt: True , IncludeSDLogos : True , AutoAddNew: True , CreateXmltv: False , ModernMediaUiPlusSupport: False
[1/25/2021 7:38:04 PM] [ INFO] SD API WebException Thrown. Message: The operation has timed out , Status: Timeout . Trying again.
[1/25/2021 7:38:04 PM] [ERROR] Failed to complete request. Exiting
[1/25/2021 7:38:04 PM] [ERROR] Did not receive a response from Schedules Direct for a token request.
[1/25/2021 7:38:04 PM] [ERROR] Failed to retrieve token from Schedules Direct. message: Did not receive a response from Schedules Direct for a token request.
[1/25/2021 7:38:04 PM] [ERROR] Failed to create MXF file. Exiting.
[1/25/2021 7:38:04 PM] [ INFO] epg123 update execution time was 00:00:03.4900048.

After this, Task Scheduler ran the EPG123 client import of the MXF file, but since it was the same MXF file that was loaded the day before, there should have not been any changes made to the DB (at least not changes that resulted in schedule changes, but correct me if I am wrong).

But if you look at the VerifyLoad logs, you can see that it did make a change...

Code: Select all

[1/25/2021 7:42:15 PM] Entering VerifyLoad()
[1/25/2021 7:43:04 PM] [ INFO] Service DISNHD: Adding schedule entry from 2/5/2021 8:55:00 AM to 2/5/2021 9:00:00 AM for program [SH03308141_0000 - [Mickey Mouse Hot Diggity-Dog Tales] - []].
[1/25/2021 7:43:04 PM] [ INFO] Service DISNHD: Removing schedule entry on 2/5/2021 8:55:00 AM for [EP03227430_0038 - [T.O.T.S.]-[s01e19 The Fly-Along; Rock-A-Bye Birdie]] due to being replaced/overlapped by another schedule entry.
[1/25/2021 7:43:11 PM] [ INFO] Checked 153639 entries and corrected 1 of them.
[1/25/2021 7:43:11 PM] Exiting VerifyLoad()
...
[1/25/2021 7:43:15 PM] [ INFO] MXF file was created on 1/24/2021 7:38:00 PM
[1/25/2021 7:43:15 PM] [ERROR] The MXF file imported is 24.09 hours old.
[1/25/2021 7:43:17 PM] [ INFO] Completed EPG123 client execution.
[1/25/2021 7:43:17 PM] [ INFO] EPG123 client execution time was 00:05:13.3629013.

As you can see, the log indicates that the MXF file was created the day before and is over 24 hours old. So it loaded the same MXF file as it loaded the day before. But you can also see that VerifyLoad found some new discrepancies between the WMC database and the MXF file.
So I am guessing that there is either a bug with the VerifyLoad that prevented it from seeing/fixing this particular issue the day before, or there is a bug with LoadMXF that caused it to make an incorrect change.

[garyan2]

This is probably going to be in my verify code. This should be enough information for me to go through the code and see what didn't work as expected. It looks like it is going wrong when I adjust the end time of a program. The first run should have added the 8:55am - 9am Mickey Mouse program.

At 8:55am - 9:30am on 2/5, what does you guide show?

[Space]

It shows the "Mickey Mouse Hot Diggity-Dog Tales" show that the 1/25 VerifyLoad update added, I don't know what it showed prior to that, although I assume it was the "T.O.T.S." show that was removed with the VerifyLoad also on the 1/25 run. I would assume that it would have also showed that same "T.O.T.S." episode at 9:00am (overlapping with the same episode airing at 8:55am).

Code: Select all

[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD at 2/5/2021 8:30:00 AM: Changing end time of [EP02647450_0231 - [Puppy Dog Pals]-[s03e07 Valentine's Day Mix-Up; A Stinky Story]] from 2/5/2021 9:00:00 AM to 2/5/2021 8:55:00 AM
[1/24/2021 7:44:17 PM] [ INFO] Service DISNHD: Adding schedule entry from 2/5/2021 9:00:00 AM to 2/5/2021 9:30:00 AM for program [EP03227430_0038 - [T.O.T.S.] - [s01e19 The Fly-Along; Rock-A-Bye Birdie]].
...
[1/25/2021 7:43:04 PM] [ INFO] Service DISNHD: Adding schedule entry from 2/5/2021 8:55:00 AM to 2/5/2021 9:00:00 AM for program [SH03308141_0000 - [Mickey Mouse Hot Diggity-Dog Tales] - []].
[1/25/2021 7:43:04 PM] [ INFO] Service DISNHD: Removing schedule entry on 2/5/2021 8:55:00 AM for [EP03227430_0038 - [T.O.T.S.]-[s01e19 The Fly-Along; Rock-A-Bye Birdie]] due to being replaced/overlapped by another schedule entry.

It looks like VerifyLoad changed "Puppy Dog Pals" end time from 9:00am to 8:55am, then added "T.O.T.S." at 9:00am. So there was now a 5-minute gap (8:55am-9:00am).

Then, the next day it removed "T.O.T.S." from 8:55am and added "Mickey Mouse Hot Diggity-Dog Tales" (which is a 5-minute program).

So it looks like somehow it missed that "T.O.T.S." actually moved from 8:55am to 9:00am and instead just added the 9:00am airing without deleting it from 8:55am. It then also neglected to add the 5-minute episode of "Mickey Mouse Hot Diggity-Dog Tales" in the spot that was left available after moving the start of "T.O.T.S" ahead 5 minutes.

[Gripweed]

Maybe I'm missing an obvious but why bother running the Client at all for MXF import and etc. if an update from SD fails?

[Space]

I think it's just the way it is set up in Task Scheduler. It runs EPG123.exe, then it runs the client. I don't think there is a way to tell Task Scheduler to only run the second one if the first one has a certain return code.

Of course, there is a way for the client to detect if the MXF file is not current (perhaps not created within the last hour) and not load it if it is not, but that has not been implemented. I don't think adding a command line option to the client to tell it to only load the MXF file if it is less than an hour or so old is a bad idea. I don't see any good coming from loading the same MXF file multiple times (other than making it easier to detect the bug that this thread is about), and I think from what Gary has said, it actually increases the size of the database needlessly when you do that.

[garyan2]

I looked at this last night, and a little today, and did find a problem with a part of an 'if' statement that would always return true. This would have led to possibly having 2 [T.O.T.S.] programs overlapping with one starting at 8:55 and the other starting at 9:00. What I don't understand is why there wasn't an 'add' of the Micky Mouse at 8:55 on the first import. I don't see how the 'if' statement problem could have caused the verify to skip a schedule entry from the mxf file. Tests I ran last night of inserting a program between two others worked correctly, but I'll try to setup more scenarios when I get a chance.

RE: importing after mxf error; the client and server programs are completely separate and stand-alone. The client has no idea if it is being run by a scheduled task, a save & execute, or by command line. It has no idea what the contents of the WMC database is to know whether the contents of the mxf file have been imported previously or not. It has no idea if it is setup to be a client only configuration scheduled to update minutes/hours after the server has created the file. Though an import of a previously imported file will unnecessarily increase the database size a little, it will be about the same increase as from a mxf file that was up-to-date. So, the client operation is as simple as it can be and will do as it is told... if told to import an mxf file, regardless of how old it is, it will import it. If there are problems, it will let you know.

[stuartm]

Wouldn't it be easy to have the task run a script that checks the results of the server step before running the client, rather than have a multi step event action?

[Space]

I looked at this last night, and a little today, and did find a problem with a part of an 'if' statement that would always return true. This would have led to possibly having 2 [T.O.T.S.] programs overlapping with one starting at 8:55 and the other starting at 9:00. What I don't understand is why there wasn't an 'add' of the Micky Mouse at 8:55 on the first import. I don't see how the 'if' statement problem could have caused the verify to skip a schedule entry from the mxf file. Tests I ran last night of inserting a program between two others worked correctly, but I'll try to setup more scenarios when I get a chance.
...

Seems to me that the things to look at are if there is any way it could be silently skipping an entry in the MXF file, if not, then is there a way it could be silently discarding that entry for some reason (perhaps due to some consistency checks), or if it could be trying to make the DB change but silently failing.

I don't pretend to know how the code has been implemented, but the first thing that came to mind when I saw this issue was that maybe it was searching chronologically forward through the schedule in the MXF and after changing the end time of "Puppy Dog Pals" from 9:00am to 8:55am, it continued searching starting at 9:00am instead of 8:55am. So it found the "T.O.T.S." add at 9:00am, but missed (skipped over) the "Mickey Mouse" add at 8:55am. Or perhaps the pointer in the WMC DB schedule was left at 9:00am instead of being pushed back to 8:55am, so that when it saw the entry for 8:55am in the MXF, it was already past that point in the WMC DB, so it was discarded.

If you are just iterating over the scheduled entries without regard to times, then this doesn't make sense, but then it would also not make sense that you missed the "Mickey Mouse" add all together.

[garyan2]

If you are just iterating over the scheduled entries without regard to times, then this doesn't make sense, but then it would also not make sense that you missed the "Mickey Mouse" add all together.

This is what I am doing which is why I am confused why there wasn't an add for "Mickey Mouse". The only thing I can think of right now is if WMC did have "Mickey Mouse" in the database at that time, but it was overlapping the end of "Puppy Dog Pals".

When I change the end time of a schedule entry, I silently change the start time of the next schedule entry in the WMC database to match the new end time. If "Mickey Mouse" was already in the database, then I would have 2 different programs starting at 8:55am (due to the bad if statement). There would have been no add for "Mickey Mouse" because it matched the contents of the mxf file. One thing I do at the beginning of the verify is catalog all the schedule entries for the service and any duplicate start time entry is dropped. The reason I point this out is for your second run, if there were 2 schedule entries that started at 8:55am, the second one was dropped. If the first for 8:55am "T.O.T.S" and the one that was dropped was "Mickey Mouse", then the verify routine would have added "Mickey Mouse" and removed "T.O.T.S" just like we see.

Talking through this, I think the cause of this is the bad "If" statement that always returned true and causing WMC to have 2 schedule entries with the same start time.

[Space]

Do you have a way of testing that this fix worked? Perhaps have something running that loads the MXF file twice every day to make sure there are not additional VerifyLoad fixes in the second run?

[garyan2]

I released v1.6.1.3 with the 'if' statement corrected along with some other goodies for the notification tray. I ran some checks last night with the 'if' statement corrected and didn't have any problems (thinking it couldn't be the cause of missing the add). I have not re-broken the 'if' statement to see if I can duplicate the issue yet. Either way, the corrected 'if' statement is out in the wild now.

[Gripweed]

I released v1.6.1.3

I'm a little concerned about this change --

[update] changed the xmltv file back to be compliant with the DRD wrt the channel contents and no longer allow the same channel id be repeated

I had to look up DRD and it says that it's an acronym for Date Rape Drug.

[garyan2]

I had to look up DRD and it says that it's an acronym for Date Rape Drug.

LOL! I meant DTD... I'll get that fixed right away. Don't need the police called on me for a typo!