1.5.0 - Verifying MXF...

[Sancho]

Just installed the latest (1.5.0.0) on three PCs, but one has been doing "Verifying MXF Load..." for an hour and a half, and counting. The other two finished the MXF Import process in "normal" time. On one PC it took 44 seconds from entering the Verify Load step to the end of the import (and end of the log file).

Should I reboot the problematic machine and re-run Save & Execute or manually import the MXF?

Thanks.

[garyan2]

Take a look at the trace.log file. It may be the notification tray didn't get the "import completed" message and just hasn't updated. It should have timed-out and updated by itself at around 1 hour 6 minutes from when the mxf file import completed.

[Sancho]

Apologies. It had only been 30 min., not 90 min. when I looked previously. Now it's been 1 hour and 40 min...

Here's the end of the trace log as copied at 11:56 AM (for reference):

Code: Select all

===============================================================================
[10/26/2020 10:16:13 AM]  Beginning epg123 client execution. version 1.5.0.0
[10/26/2020 10:16:13 AM] ===============================================================================
[10/26/2020 10:16:13 AM] [ INFO] Beginning epg123 client execution. 2020-10-26 14:16:13Z
[10/26/2020 10:16:13 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: True
[10/26/2020 10:16:14 AM] Entering importMxfFile() for file "c:\programdata\garyan2\epg123\output\epg123.mxf"
[10/26/2020 10:19:08 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/26/2020 10:19:08 AM] Exiting importMxfFile(). SUCCESS.
[10/26/2020 10:19:08 AM] Entering VerifyLoad()

[garyan2]

Let's try a reboot and then run the following in a command prompt.

Code: Select all

"c:\program files (x86)\epg123\epg123client.exe" -i c:\programdata\garyan2\epg123\output\epg123.mxf -verbose

When was your last garbage collection? I notice it takes ~3 minutes to import the file. Is that typical?

[Sancho]

Let's try a reboot and then run the following in a command prompt.

Code: Select all

"c:\program files (x86)\epg123\epg123client.exe" -i c:\programdata\garyan2\epg123\output\epg123.mxf -verbose

When was your last garbage collection? I notice it takes ~3 minutes to import the file. Is that typical?

Last garbage collection was on 10/24.
Times for non-GC imports range from ~2:34 to 3 min., most in the 2:45 range.

I assume that command will just write more to the trace log, yes? Rebooting now, then will run it. Should I post some results here, or send you the trace log after some time?

[garyan2]

Yes, it will just put more information in the trace.log file during the verification. I don't know how useful it will be, but we may get something. I think 5 minutes after verification starts should be more than enough time if it doesn't complete. If after 5 minutes it isn't doing anything, please send me the trace.log file to support@garyan2.net.

[Sancho]

Perhaps due to the verbosity, there are now entries after the "Entering VerifyLoad()" line, but then it stalls. It was about 8-9 minutes after stalling that I copied the active log. I'll send that and the previous log file, as a new one was generated during the manual import.

Any ideas on how to get around this? Should I revert to the previous version (v1.4.10.10) for now?

[garyan2]

Interesting. Could you repeat the reboot and manual run again? I want to see if it does another chunk of stations.

How much memory does this station have?

[Sancho]

Just got home. Rebooting it again now. I checked and it was still in the same state, trace log stalled at 12:42 PM (according to Windows Explorer). So that's 6+ hours of spinning its wheels.

I'll run the command and once the trace log seems stalled, I'll send you the latest.

8 GB of RAM; system disk is a WD Blue SSD (IIRC), with a 2 TB HDD for recordings. Before I switched this one to the SSD, the full morning update process was taking 20-30 min

[garyan2]

Well, that's actually not what I was expecting. Evidently those hundreds of changes that the client is doing don't get committed until the store has been closed. I was expecting it to pick up where it left off.

Could you run the command line 1 more time, but this time monitor how much memory epg123Client.exe is using in the Task Manager? You have plenty of memory, but I think there might be problems if it reaches close to 2GB. My tests here would get to a little over 1GB when doing the verification with 971 stations compared with your 626.

[Sancho]

So, as soon as the MXF Loader process ended, peaking at around 505,000 K, the epg123client process assumed the heavy load (the verification stage, I reckon), rapidly escalated to ~729,000 K, then died. As you might expect, that's when the trace log stopped being written to.

I compared the most recent entries in the trace log to the first one I sent you: ends at the exact same entry, unlike the second one I sent that had one more. So, runs 1 and 3 seem to be identical in that regard. I can send it, if you like, but I don't think there's a point.

Since the import was successful, does that mean the guide data is up-to-date? Or should I re-install the previous version? Or should I await further instructions? I don't mind being the guinea pig.

[garyan2]

Hmm. Looks like I've been barking up the wrong tree. There must be something wrong with the database that I haven't seen. Your WMC is kinda updated... the guide and pvr reindexing hasn't occurred so searching and possibly your recording schedule hasn't been updated.

I don't know how you use this particular machine, but you've got a couple options other than downgrading to v1.4.10.10.
1. You could [Rebuild WMC Database] to clear out whatever is going on there. You will lose your recording history but it will be a clean database.
2. Tedious, and can take a while, but in the client there is a new option to 'Clear guide listings'. You can select multiple channels, or even all channels, and clear the listings. I would suggest running garbage collection after doing this to make sure the schedule entries are completely removed and then run the command again.

[jamestx10]

I look to be in the same boat. Installed the 1.5 update yesterday. Scheduled task ran this morning and stopped at :

Code: Select all

[10/27/2020 3:06:31 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/27/2020 3:06:31 AM] Exiting importMxfFile(). SUCCESS.
[10/27/2020 3:06:31 AM] Entering VerifyLoad()

I manually ran it and it stopped there as well. Came here to search for the problem and found this thread. I ran the verbose option and did not see RAM usage go over 600 MB (32GB total on this machine).

[garyan2]

Could either of you download the updated epg123client.exe and try the command line with it? Unzip it to your drive and then copy into the c:\program files (x86)\epg123 folder. I added a couple more log entries as well as 1 change for a possible WMC schedule entry issue.

[StinkyImp]

I look to be in the same boat. Installed the 1.5 update yesterday.

#MeToo

Normally it completes processing within a second of the "Exiting importMxfFile(). SUCCESS." entry. Today it stopped at "Entering VerifyLoad()".

Interesting note... There are no EPG123 programs running in the Task Manager. It's like it simply stopped processing and quietly exited?

Code: Select all

EPG123 Log Parser (and Report Generator) - v 1.7.6 (64 bit)
Report Created on 10/27/2020 at 08:01:30
================================================================
[10/26/2020 12:15:23 AM] ===============================================================================
[10/26/2020 12:15:23 AM]  Beginning epg123 client execution. version 1.4.10.0
[10/26/2020 12:15:23 AM] ===============================================================================
[10/26/2020 12:15:23 AM] [ INFO] Beginning epg123 client execution. 2020-10-26 07:15:23Z
[10/26/2020 12:15:23 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: False
[10/26/2020 12:15:24 AM] [ INFO] Recording in progress: 12:00 AM - 01:00 AM
[10/26/2020 12:15:24 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 01:04:00
[10/26/2020 1:04:00 AM] [ INFO] Recording in progress: 01:00 AM - 01:30 AM
[10/26/2020 1:04:00 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 01:34:00
[10/26/2020 1:34:00 AM] Entering PerformGarbageCleanup().
[10/26/2020 1:41:44 AM] [ INFO] Successfully completed garbage cleanup. Exit code: 0
[10/26/2020 1:41:44 AM] Exiting PerformGarbageCleanup(). SUCCESS.
[10/26/2020 1:41:44 AM] Entering importMxfFile() for file  c:\epg123\output\epg123.mxf 
[10/26/2020 1:42:07 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/26/2020 1:42:07 AM] Exiting importMxfFile(). SUCCESS.
[10/26/2020 1:42:07 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[10/26/2020 1:42:07 AM] [ INFO] Completed lineup refresh.
[10/26/2020 1:42:07 AM] Entering runWmcTask(ReindexSearchRoot)
[10/26/2020 1:42:07 AM] [ INFO] SUCCESS: Attempted to run the scheduled task  Microsoft\Windows\Media Center\ReindexSearchRoot .
[10/26/2020 1:42:07 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[10/26/2020 1:42:07 AM] Exiting runWmcTask(ReindexSearchRoot). SUCCESS.
[10/26/2020 1:42:07 AM] [ INFO] MXF file was created on 10/26/2020 12:15:07 AM
[10/26/2020 1:42:07 AM] [ INFO] Completed EPG123 client execution.
[10/26/2020 1:42:07 AM] [ INFO] EPG123 client execution time was 01:26:43.9555588.

[10/27/2020 12:15:23 AM] ===============================================================================
[10/27/2020 12:15:23 AM]  Beginning epg123 client execution. version 1.5.0.0
[10/27/2020 12:15:23 AM] ===============================================================================
[10/27/2020 12:15:23 AM] [ INFO] Beginning epg123 client execution. 2020-10-27 07:15:23Z
[10/27/2020 12:15:23 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: False
[10/27/2020 12:15:23 AM] [ INFO] Recording in progress: 12:00 AM - 01:00 AM
[10/27/2020 12:15:23 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 01:04:00
[10/27/2020 1:04:00 AM] Entering importMxfFile() for file  c:\epg123\output\epg123.mxf 
[10/27/2020 1:04:25 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/27/2020 1:04:25 AM] Exiting importMxfFile(). SUCCESS.
[10/27/2020 1:04:25 AM] Entering VerifyLoad()

===== QUERY INFORMATION (Predefined) ===========================
Logs used:		trace.log ONLY
Search String:		Everything
Date Range:		10/26/2020 thru 10/27/2020 (2 days)
Total results found:	137
Query time:		08 seconds

===== GENERAL INFORMATION ======================================
Log Path:		C:\epg123\
Logfile timespan:	5/19/2020 thru 10/27/2020 (162 days)
Total lines processed:	10850

===== SYSTEM INFORMATION =======================================
Operating System:	Windows 7 Professional (64 bit)
Processor:		Intel(R) Core(TM) i3-3220 CPU @ 3.30GHz
Total RAM:		8.00 GB
ehshell version:	6.1.7601.23434
EPG123 version:		1.5.0.0
Last boot time:		October 25, 2020 - 06:40 AM
System Uptime:		02 Days 01 Hours 21 Minutes

The history for the scheduled "epg123_update" task indicates that it completed successfully at 1:04:28 AM.

[jamestx10]

I removed a few channels that I don't use and ran the save and execute and it completed this time

Code: Select all

[10/27/2020 10:42:47 AM]  Beginning epg123 client execution. version 1.5.0.0
[10/27/2020 10:42:47 AM] ===============================================================================
[10/27/2020 10:42:47 AM] [ INFO] Beginning epg123 client execution. 2020-10-27 15:42:47Z
[10/27/2020 10:42:47 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: True
[10/27/2020 10:42:48 AM] Entering importMxfFile() for file "f:\epg123\output\epg123.mxf"
[10/27/2020 10:44:28 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/27/2020 10:44:28 AM] Exiting importMxfFile(). SUCCESS.
[10/27/2020 10:44:28 AM] Entering VerifyLoad()
[10/27/2020 10:44:37 AM] [ INFO] Checked 67242 entries and corrected 372 of them.
[10/27/2020 10:44:37 AM] Exiting VerifyLoad()
[10/27/2020 10:44:38 AM] [ INFO] Removing HALLDRS from channel 237 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:38 AM] [ INFO] Removing NIKP from channel 253 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:38 AM] [ INFO] Removing IMPCNET from channel 292 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:38 AM] [ INFO] Removing KXASDT3 from channel 461 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing OVATNHD from channel 688 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing ELREYHD from channel 698 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing GACHD from channel 723 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing SUNDHD from channel 735 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing TVONEHD from channel 771 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing GALAHD from channel 774 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing SHOBETH from channel 867 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing SHOBEHP from channel 868 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:41 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[10/27/2020 10:44:41 AM] [ INFO] Completed lineup refresh.
[10/27/2020 10:44:41 AM] Entering runWmcTask(ReindexSearchRoot)
[10/27/2020 10:44:41 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[10/27/2020 10:44:41 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[10/27/2020 10:44:41 AM] Exiting runWmcTask(ReindexSearchRoot). SUCCESS.
[10/27/2020 10:44:41 AM] [ INFO] MXF file was created on 10/27/2020 10:42:31 AM

[garyan2]

I removed a few channels that I don't use and ran the save and execute and it completed this time

Code: Select all

[10/27/2020 10:42:47 AM]  Beginning epg123 client execution. version 1.5.0.0
[10/27/2020 10:42:47 AM] ===============================================================================
[10/27/2020 10:42:47 AM] [ INFO] Beginning epg123 client execution. 2020-10-27 15:42:47Z
[10/27/2020 10:42:47 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: True
[10/27/2020 10:42:48 AM] Entering importMxfFile() for file "f:\epg123\output\epg123.mxf"
[10/27/2020 10:44:28 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/27/2020 10:44:28 AM] Exiting importMxfFile(). SUCCESS.
[10/27/2020 10:44:28 AM] Entering VerifyLoad()
[10/27/2020 10:44:37 AM] [ INFO] Checked 67242 entries and corrected 372 of them.
[10/27/2020 10:44:37 AM] Exiting VerifyLoad()
[10/27/2020 10:44:38 AM] [ INFO] Removing HALLDRS from channel 237 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:38 AM] [ INFO] Removing NIKP from channel 253 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:38 AM] [ INFO] Removing IMPCNET from channel 292 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:38 AM] [ INFO] Removing KXASDT3 from channel 461 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing OVATNHD from channel 688 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing ELREYHD from channel 698 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing GACHD from channel 723 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing SUNDHD from channel 735 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing TVONEHD from channel 771 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing GALAHD from channel 774 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing SHOBETH from channel 867 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:39 AM] [ INFO] Removing SHOBEHP from channel 868 in lineup EPG123 Frontier Fios Keller - Digital (Keller).
[10/27/2020 10:44:41 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[10/27/2020 10:44:41 AM] [ INFO] Completed lineup refresh.
[10/27/2020 10:44:41 AM] Entering runWmcTask(ReindexSearchRoot)
[10/27/2020 10:44:41 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[10/27/2020 10:44:41 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[10/27/2020 10:44:41 AM] Exiting runWmcTask(ReindexSearchRoot). SUCCESS.
[10/27/2020 10:44:41 AM] [ INFO] MXF file was created on 10/27/2020 10:42:31 AM

Thanks. At least this verifies there is something in the database that the client couldn't handle. Hopefully the updated client will handle it or point me in the right direction. Someone else in the same situation can pick it up (@StinkyImp ?)

[StinkyImp]

Someone else in the same situation can pick it up (@StinkyImp ?)

I rolled back to 1.4.10.10 and everything went as expected. I re-rolled 1.5.0.0 (with the 1.5.0.10 client) and it stopped at "Entering VerifyLoad()" and the Task scheduler history indicates that it completed successfully.

Note: The EPG grid is perfect as well as the scheduled recordings.

Code: Select all

[10/27/2020 9:02:00 AM] ===============================================================================
[10/27/2020 9:02:00 AM]  Beginning epg123 client execution. version 1.5.0.10
[10/27/2020 9:02:00 AM] ===============================================================================
[10/27/2020 9:02:00 AM] [ INFO] Beginning epg123 client execution. 2020-10-27 16:02:00Z
[10/27/2020 9:02:00 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: False
[10/27/2020 9:02:01 AM] Entering importMxfFile() for file "c:\epg123\output\epg123.mxf"
[10/27/2020 9:02:22 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[10/27/2020 9:02:22 AM] Exiting importMxfFile(). SUCCESS.
[10/27/2020 9:02:22 AM] Entering VerifyLoad()

[garyan2]

Did you use the command line above? I need the "-verbose" switch in the command line to see more information in the log.

viewtopic.php?p=142290#p142290

[StinkyImp]

Did you use the command line above?

Sorry! Didn't see that. I sent you a PM.