Error when running PerformGarbageCleanup during recording?

[RyC]

Hello,

My EPG123 scheduled task is set to run at 9am, and usually nothing is recording at that time but when something is, EPG123 has previously worked fine waiting until all recordings are finished to do the import. I recently updated to 1.3.8.20, and I've been following the thread on how this new version triggers the WMC garbage cleanup task as part of the import process.

Yesterday, there was a marathon and the computer was recording from 9am-1am solid. According to the logs, EPG123 waited until there were no more recordings to perform the import, but it did run PerformGarbageCleanup from 9am-9:16am while a recording was in progress.

At 1:07am, just a few minutes after EPG123 seemed to successfully import the guide, there is a Warning event from mcstore "Recovery of guide listings and recording schedule is complete.". I couldn't open WMC until I restarted the computer (a warning box popped up with a generic "can't open WMC" error). After I restarted, WMC opened normally but popped up the "Guide recovered please check your schedules" error box. It looked like the entire WMC database was reset, the guide was empty and it seemed WMC needed to rescan my Recorded TV folder from scratch.

I guess my question is, could EPG123 running the garbage cleanup while WMC was recording cause this problem, did recording for 16 hours straight cause an issue, or is it a total coincidence? My WMC computer was also set up years ago, so it was running the garbage cleanup task on its own at the normal interval (I think).

I've attached the log below, thanks for your help!

Code: Select all

[7/9/2020 9:00:26 AM] ===============================================================================
[7/9/2020 9:00:26 AM]  Beginning epg123 client execution. version 1.3.8.20
[7/9/2020 9:00:26 AM] ===============================================================================
[7/9/2020 9:00:26 AM] [ INFO] Beginning epg123 client execution. 2020-07-09 16:00:26Z
[7/9/2020 9:00:26 AM] [ INFO] Import: True , Match: True , NoLogo: False , Force: False , ShowProgress: False
[7/9/2020 9:00:26 AM] Entering PerformGarbageCleanup().
[7/9/2020 9:16:54 AM] [ INFO] Successfully complete garbage cleanup. Exit code: 0
[7/9/2020 9:16:54 AM] Exiting PerformGarbageCleanup(). SUCCESS.
[7/9/2020 9:16:55 AM] [ INFO] Recording in progress: 09:00 AM - 10:16 AM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Magic Man
[7/9/2020 9:16:56 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 10:16:56
[7/9/2020 10:16:57 AM] [ INFO] Recording in progress: 10:16 AM - 11:20 AM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: 50% Off
[7/9/2020 10:16:58 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 11:16:58
[7/9/2020 11:16:59 AM] [ INFO] Recording in progress: 10:16 AM - 11:20 AM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: 50% Off
[7/9/2020 11:16:59 AM] [ INFO] Recording in progress: 11:20 AM - 12:35 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: The Guy for This
[7/9/2020 11:16:59 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 12:16:59
[7/9/2020 12:17:01 PM] [ INFO] Recording in progress: 11:20 AM - 12:35 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: The Guy for This
[7/9/2020 12:17:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 12:39:00
[7/9/2020 12:39:01 PM] [ INFO] Recording in progress: 12:35 PM - 01:40 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Namaste
[7/9/2020 12:39:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 13:39:01
[7/9/2020 1:39:03 PM] [ INFO] Recording in progress: 12:35 PM - 01:40 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Namaste
[7/9/2020 1:39:03 PM] [ INFO] Recording in progress: 01:40 PM - 02:50 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Dedicado a Max
[7/9/2020 1:39:03 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 14:39:03
[7/9/2020 2:39:05 PM] [ INFO] Recording in progress: 01:40 PM - 02:50 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Dedicado a Max
[7/9/2020 2:39:05 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 14:54:00
[7/9/2020 2:54:01 PM] [ INFO] Recording in progress: 02:50 PM - 04:00 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Wexler v. Goodman
[7/9/2020 2:54:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 15:54:01
[7/9/2020 3:54:03 PM] [ INFO] Recording in progress: 02:50 PM - 04:00 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Wexler v. Goodman
[7/9/2020 3:54:03 PM] [ INFO] Recording in progress: 04:00 PM - 05:07 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: JMM
[7/9/2020 3:54:03 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 16:54:03
[7/9/2020 4:54:05 PM] [ INFO] Recording in progress: 04:00 PM - 05:07 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: JMM
[7/9/2020 4:54:05 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 17:11:00
[7/9/2020 5:11:01 PM] [ INFO] Recording in progress: 05:07 PM - 06:22 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Bagman
[7/9/2020 5:11:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 18:11:01
[7/9/2020 6:11:03 PM] [ INFO] Recording in progress: 05:07 PM - 06:22 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Bagman
[7/9/2020 6:11:03 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 18:26:00
[7/9/2020 6:26:01 PM] [ INFO] Recording in progress: 06:22 PM - 07:48 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Bad Choice Road
[7/9/2020 6:26:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 19:26:01
[7/9/2020 7:26:03 PM] [ INFO] Recording in progress: 06:22 PM - 07:48 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Bad Choice Road
[7/9/2020 7:26:03 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 19:52:00
[7/9/2020 7:52:00 PM] [ INFO] Recording in progress: 08:00 PM - 09:00 PM on channel 1009 KEZIDT -> Holey Moley - Love at First Stroke
[7/9/2020 7:52:00 PM] [ INFO] Recording in progress: 08:00 PM - 08:30 PM on channel 1734 TOONPHD -> Bob's Burgers - Into the Mild
[7/9/2020 7:52:00 PM] [ INFO] Recording in progress: 07:48 PM - 09:15 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Something Unforgivable
[7/9/2020 7:52:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 20:52:01
[7/9/2020 8:52:01 PM] [ INFO] Recording in progress: 08:00 PM - 09:00 PM on channel 1009 KEZIDT -> Holey Moley - Love at First Stroke
[7/9/2020 8:52:02 PM] [ INFO] Recording in progress: 07:48 PM - 09:15 PM on channel 1405 AMCPHD -> Better Call Saul - Bonus Edition: Something Unforgivable
[7/9/2020 8:52:03 PM] [ INFO] Recording in progress: 08:30 PM - 09:00 PM on channel 1492 HGTVPHD -> Flip or Flop - Risky Business: Small House, Big Problems
[7/9/2020 8:52:03 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 21:19:00
[7/9/2020 9:19:00 PM] [ INFO] Recording in progress: 09:00 PM - 09:30 PM on channel 1734 TOONPHD -> American Dad - Failure Is Not a Factory-Installed Option
[7/9/2020 9:19:00 PM] [ INFO] Recording in progress: 09:30 PM - 10:00 PM on channel 1734 TOONPHD -> American Dad - Lincoln Lover
[7/9/2020 9:19:02 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 22:04:00
[7/9/2020 10:04:01 PM] [ INFO] Recording in progress: 10:00 PM - 10:30 PM on channel 1430 TRUTVHP -> Impractical Jokers - Dinner Party Show 7
[7/9/2020 10:04:02 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 22:34:00
[7/9/2020 10:34:00 PM] [ INFO] Recording in progress: 10:31 PM - 11:01 PM on channel 1492 HGTVPHD -> House Hunters - Hunting for a Cabin in Broken Bow
[7/9/2020 10:34:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 23:05:00
[7/9/2020 11:05:00 PM] [ INFO] Recording in progress: 11:00 PM - 11:30 PM on channel 1734 TOONPHD -> Family Guy - Brokeback Swanson
[7/9/2020 11:05:01 PM] [ INFO] Recording in progress: 11:00 PM - 11:30 PM on channel 1434 TBSHDP -> Conan - Conan
[7/9/2020 11:05:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 23:34:00
[7/9/2020 11:34:01 PM] [ INFO] Recording in progress: 11:30 PM - 12:00 AM on channel 1734 TOONPHD -> Family Guy - The Peanut Butter Kid
[7/9/2020 11:34:01 PM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 00:04:00
[7/10/2020 12:04:00 AM] [ INFO] Recording in progress: 12:00 AM - 01:01 AM on channel 1492 HGTVPHD -> Flipping Across America - Flipping Across America
[7/10/2020 12:04:02 AM] [ INFO] Delaying import while WMC is recording. Will check recording status again at 01:04:02
[7/10/2020 1:04:05 AM] Entering importMxfFile() for file "c:\epg123\output\epg123.mxf"
[7/10/2020 1:05:09 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[7/10/2020 1:05:09 AM] Exiting importMxfFile(). SUCCESS.
[7/10/2020 1:05:15 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[7/10/2020 1:05:15 AM] [ INFO] Completed lineup refresh.
[7/10/2020 1:05:15 AM] Entering runWmcTask(ReindexSearchRoot)
[7/10/2020 1:05:15 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[7/10/2020 1:05:15 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[7/10/2020 1:05:15 AM] Exiting runWmcTask(ReindexSearchRoot). SUCCESS.
[7/10/2020 1:05:15 AM] Entering runWmcTask(PvrScheduleTask)
[7/10/2020 1:05:15 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\PvrScheduleTask".
[7/10/2020 1:05:15 AM] [ INFO] Successfully started the PvrScheduleTask task. Exit code: 0
[7/10/2020 1:05:15 AM] Exiting runWmcTask(PvrScheduleTask). SUCCESS.
[7/10/2020 1:05:15 AM] [ INFO] Completed EPG123 client execution.
[7/10/2020 1:05:15 AM] [ INFO] EPG123 client execution time was 16:04:49.1756483.

[IT Troll]

The database recovery task runs (if required) when you next launch the Media Center UI. So the event that triggered the recovery can have happened any time before that, since the UI was last launched.

If you tend to always leave the UI open (I do) this means it can be hard to trace back what might have caused the problem. If you are able, I would move the EPG123 import/maintenance task to a time when you can be sure that nothing else is happening.

[garyan2]

Not sure if it is related to garbage cleanup running during a recording. My experiment in that area was to run it while I was recording 4 streams at the same time with no ill effects. Granted, my database is probably considerably smaller than yours and only took about 2 minutes, but it didn't interrupt the recordings nor did it crash the mcstore. How long have you been running 1.3.8.20? Was this the first time EPG123 ran the garbage cleanup?

The timing of the mcstore event means it was probably during the ReindexSearchRoot/PvrScheduleTask tasks running. There will be a change in the next release to only run the ReindexSearchRoot task because apparently the PvrScheduleTask is performed after the ReindexSearchRoot completes automatically. Running both in parallel may have contributed to this but this is the way EPG123 has been doing it for years.

The curiosity in your description above of not being able to open WMC. I've never seen this happen... may be due to the mcstore crash. Do you have optimization enabled (settings->General->Optimization)? Whatever optimization does, it will prevent WMC from opening and my experience says it increases the likelihood of a "recovery" occurring.

[RyC]

Thanks Gary and IT Troll,

My garbage cleanups (even when WMC runs them on its own) have taken around 15-20 minutes for several years now. I do have almost 9000 recordings so that definitely could be part of it. I've been running 1.3.8.20 since July 4th, so just under a week, and I think this was the second time EPG123 ran the garbage cleanup. I think WMC ran garbage cleanup once on its own as part of the old scheduled task during the week as well.

You're right, Optimization is checked, and I think it's been checked ever since I started WMC pre-EPG123. I think I've heard you mention how it causes issues before, I will uncheck it if it's preferred. Sorry I didn't grab the exact error message that popped when WMC wouldn't open, it was super late.

Interesting that it was probably during ReindexSearchRoot/PvrScheduleTask. WMC was fully closed, and I've not run into this error before. Thanks for your help with this, the timing with the new EPG123 update just got me wondering if there was a potential issue with garbage cleanup.