Error on log during nightly update

[DSperber]

Ok, what have I done wrong.

Newly installed WMC system and EPG123 v1.1.0 (originally), updated to v1.1.1. I now see there's a 1.1.2 so I guess I should upgrade again.

Theoretically things are working fine as I can manually run EPG123.exe during the day and the Guide gets updated just fine. But when I look at the log the next morning, for some reason SD is apparently rejecting something about the overnight automatic 2AM connection as "forbidden" whatever that means.

What have I done wrong, or what can I do to correct this?

Code: Select all

[2/27/2017 12:44:08 AM] ===============================================================================
[2/27/2017 12:44:08 AM]  Activating the epg123 configuration GUI.
[2/27/2017 12:44:08 AM] ===============================================================================
[2/27/2017 12:44:09 AM] [ INFO] epg123 is up to date. version: 1.1.1
[2/27/2017 12:44:09 AM] [ INFO] Successfully queried the Task Scheduler for status. status: Ready. Last Run 2/26/2017 2:00:00 AM; Exit: 0x00000000.
[2/27/2017 12:44:10 AM] [ INFO] Token request successful. serverID: 20141201.web.3
[2/27/2017 12:44:10 AM] [ INFO] Status request successful. account expires: 2017-04-21T07:19:18Z , lineups: 2/4 , lastDataUpdate: 2017-02-27T05:16:31Z
[2/27/2017 12:44:10 AM] [ INFO] system status: Online , message: No known issues.
[2/27/2017 12:44:10 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[2/27/2017 12:44:10 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-CA57315-X.
[2/27/2017 12:44:11 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-OTA-90292.
[2/27/2017 12:44:32 AM] ===============================================================================
[2/27/2017 12:44:32 AM]  Beginning epg123 update execution.
[2/27/2017 12:44:32 AM] ===============================================================================
[2/27/2017 12:44:32 AM] [ INFO] Successfully retrieved TMDb configurations.
[2/27/2017 12:44:32 AM] [ INFO] epg123 version 1.1.1 , DaysToDownload: 28 , PrefixEpisodeTitle: True , AppendEpisodeDesc: True , TMDbCoverArt: True , LogoOverride: True , AutoAddNew: True
[2/27/2017 12:44:33 AM] [ INFO] Token request successful. serverID: 20141201.web.3
[2/27/2017 12:44:33 AM] [ INFO] epg123 is up to date. version: 1.1.1
[2/27/2017 12:44:33 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[2/27/2017 12:44:33 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-CA57315-X.
[2/27/2017 12:44:33 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-OTA-90292.
[2/27/2017 12:44:33 AM] Entering getAllScheduleEntryMd5s() for 28 days on 83 stations.
[2/27/2017 12:44:35 AM] [ INFO] Successfully retrieved Md5s for 83 station's daily schedules.
[2/27/2017 12:44:37 AM] [ INFO] Successfully retrieved 83 station's daily schedules.
[2/27/2017 12:44:45 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[2/27/2017 12:44:45 AM] Entering buildAllProgramEntries() for 16490 programs.
[2/27/2017 12:45:22 AM] [ INFO] Successfully retrieved 2005 programs metadata.
[2/27/2017 12:45:31 AM] Exiting buildAllProgramEntries(). SUCCESS.
[2/27/2017 12:45:31 AM] Entering buildAllGenericSeriesInfoDescriptions() for 2275 series.
[2/27/2017 12:45:36 AM] [ INFO] Successfully retrieved 139 programs generic description metadata.
[2/27/2017 12:45:36 AM] Exiting buildAllGenericSeriesInfoDescriptions(). SUCCESS.
[2/27/2017 12:45:36 AM] Entering getAllMoviePosters() for 1788 movies.
[2/27/2017 12:45:36 AM] [ INFO] Successfully retrieved artwork info for 124 programs.
[2/27/2017 12:45:37 AM] [ INFO] TMDb catalog search for "Mommy's Secret" from 2016 found 1 results.
[2/27/2017 12:45:37 AM] [ INFO] TMDb catalog search for "Killing Mommy" from 2016 found 1 results.
[2/27/2017 12:45:37 AM] [ INFO] TMDb catalog search for "Mommy's Little Girl" from 2016 found 1 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Mommy's Little Boy" from 2017 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Mommy's Little Boy" from 2018 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Mommy's Little Boy" from 2016 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Double Mommy" from 2017 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Double Mommy" from 2018 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Double Mommy" from 2016 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "A Father's Secret" from 2016 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "A Father's Secret" from 2017 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "A Father's Secret" from 2015 found 0 results.
[2/27/2017 12:45:38 AM] [ INFO] TMDb catalog search for "Beaches" from 2017 found 1 results.
[2/27/2017 12:45:39 AM] [ INFO] TMDb catalog search for "Flashback" from 2016 found 0 results.
[2/27/2017 12:45:39 AM] [ INFO] TMDb catalog search for "Flashback" from 2017 found 0 results.
[2/27/2017 12:45:39 AM] [ INFO] TMDb catalog search for "Flashback" from 2015 found 1 results.
[2/27/2017 12:45:39 AM] [ INFO] TMDb catalog search for "Gold Rush Maisie" from 1940 found 1 results.
[2/27/2017 12:45:39 AM] Exiting getAllMoviePosters(). SUCCESS.
[2/27/2017 12:45:39 AM] Entering getAllSeriesImages() for 2275 series.
[2/27/2017 12:45:40 AM] [ INFO] Successfully retrieved artwork info for 500 programs.
[2/27/2017 12:45:42 AM] [ INFO] Successfully retrieved artwork info for 379 programs.
[2/27/2017 12:45:43 AM] Exiting getAllSeriesImages(). SUCCESS.
[2/27/2017 12:45:43 AM] Entering writeMxf().
[2/27/2017 12:45:44 AM] Exiting writeMxf(). SUCCESS.
[2/27/2017 12:45:44 AM] Entering writeImageArchive().
[2/27/2017 12:45:44 AM] Exiting writeImageArchive(). SUCCESS.
[2/27/2017 12:45:46 AM] [ INFO] 2998 files deleted from the cache directory during cleanup.
[2/27/2017 12:45:46 AM] [STATS] Generated .mxf file contains 83 services, 2275 series, 16490 programs, and 32797 people with 4000 image links.
[2/27/2017 12:45:46 AM] ====================== Beginning epg123 client execution. =====================
[2/27/2017 12:45:46 AM] [ INFO] Import=True , Match=True , NoLogo=False
[2/27/2017 12:45:46 AM] [ INFO] import filename = epg123.mxf
[2/27/2017 12:46:14 AM] [ INFO] Successfully imported .mxf file into Media Center. Exit code: 0
[2/27/2017 12:46:16 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[2/27/2017 12:46:16 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[2/27/2017 12:46:16 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[2/27/2017 12:46:16 AM] [STATS] epg123Client mxf load and database reindex execution time was 00:00:29.8445000.
[2/27/2017 12:46:16 AM] ====================== Completed epg123 client execution. =====================
[2/27/2017 12:46:18 AM] [STATS] epg123 update execution time was 00:01:45.8790000.
[2/27/2017 2:00:00 AM] ===============================================================================
[2/27/2017 2:00:00 AM]  Beginning epg123 update execution.
[2/27/2017 2:00:00 AM] ===============================================================================
[2/27/2017 2:00:03 AM] [ INFO] Successfully retrieved TMDb configurations.
[2/27/2017 2:00:03 AM] [ INFO] epg123 version 1.1.1 , DaysToDownload: 28 , PrefixEpisodeTitle: True , AppendEpisodeDesc: True , TMDbCoverArt: True , LogoOverride: True , AutoAddNew: True
[2/27/2017 2:00:04 AM] [ INFO] Token request successful. serverID: 20141201.web.3
[2/27/2017 2:00:04 AM] [ INFO] epg123 is up to date. version: 1.1.1
[2/27/2017 2:00:04 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[2/27/2017 2:00:04 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-CA57315-X.
[2/27/2017 2:00:05 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-OTA-90292.
[2/27/2017 2:00:05 AM] Entering getAllScheduleEntryMd5s() for 28 days on 83 stations.
[2/27/2017 2:00:10 AM] [ INFO] Successfully retrieved Md5s for 83 station's daily schedules.
[2/27/2017 2:00:12 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[2/27/2017 2:00:12 AM] Entering buildAllProgramEntries() for 16490 programs.
[2/27/2017 2:00:19 AM] [ERROR] SD API WebException Thrown. Message: The remote server returned an error: (403) Forbidden. , Status: ProtocolError
[2/27/2017 2:00:19 AM] [ERROR] SD responded with error code: 4003 , message: Invalid username or token has expired. , serverID: 20141201.web.3 , datetime: 2017-02-27T10:00:18Z
[2/27/2017 2:00:19 AM] [ERROR] Did not receive a response from Schedules Direct for 1 programs metadata.
[2/27/2017 2:00:19 AM] Problem occurred during buildProgramEntries(). Exiting.
[2/27/2017 2:00:19 AM] [ERROR] Failed to create MXF file. Exiting.
[2/27/2017 2:00:19 AM] [STATS] epg123 update execution time was 00:00:18.4570000.
[2/27/2017 2:00:19 AM] ====================== Beginning epg123 client execution. =====================
[2/27/2017 2:00:19 AM] [ INFO] Import=True , Match=True , NoLogo=False
[2/27/2017 2:00:19 AM] [ INFO] import filename = epg123.mxf
[2/27/2017 2:00:41 AM] [ INFO] Successfully imported .mxf file into Media Center. Exit code: 0
[2/27/2017 2:00:42 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[2/27/2017 2:00:42 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[2/27/2017 2:00:42 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[2/27/2017 2:00:42 AM] [STATS] epg123Client mxf load and database reindex execution time was 00:00:23.1900000.
[2/27/2017 2:00:42 AM] ====================== Completed epg123 client execution. =====================
[2/28/2017 2:00:00 AM] ===============================================================================
[2/28/2017 2:00:00 AM]  Beginning epg123 update execution.
[2/28/2017 2:00:00 AM] ===============================================================================
[2/28/2017 2:00:02 AM] [ INFO] Successfully retrieved TMDb configurations.
[2/28/2017 2:00:02 AM] [ INFO] epg123 version 1.1.1 , DaysToDownload: 28 , PrefixEpisodeTitle: True , AppendEpisodeDesc: True , TMDbCoverArt: True , LogoOverride: True , AutoAddNew: True
[2/28/2017 2:00:03 AM] [ INFO] Token request successful. serverID: 20141201.web.3
[2/28/2017 2:00:03 AM] [ INFO] epg123 is not up to date. Latest version is 1.1.2 and can be downloaded from http://epg123.garyan2.net.
[2/28/2017 2:00:03 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[2/28/2017 2:00:03 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-CA57315-X.
[2/28/2017 2:00:04 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-OTA-90292.
[2/28/2017 2:00:04 AM] Entering getAllScheduleEntryMd5s() for 28 days on 83 stations.
[2/28/2017 2:00:08 AM] [ INFO] Successfully retrieved Md5s for 83 station's daily schedules.
[2/28/2017 2:00:09 AM] [ERROR] SD API WebException Thrown. Message: The remote server returned an error: (403) Forbidden. , Status: ProtocolError
[2/28/2017 2:00:09 AM] [ERROR] SD responded with error code: 4003 , message: Invalid username or token has expired. , serverID: 20141201.web.3 , datetime: 2017-02-28T10:00:07Z
[2/28/2017 2:00:09 AM] [ERROR] Did not receive a response from Schedules Direct for 83 station's daily schedules.
[2/28/2017 2:00:09 AM] [ERROR] Problem occurred during getMd5ScheduleEntries(). Exiting.
[2/28/2017 2:00:09 AM] [ERROR] Failed to create MXF file. Exiting.
[2/28/2017 2:00:09 AM] [STATS] epg123 update execution time was 00:00:08.2700000.
[2/28/2017 2:00:09 AM] ====================== Beginning epg123 client execution. =====================
[2/28/2017 2:00:09 AM] [ INFO] Import=True , Match=True , NoLogo=False
[2/28/2017 2:00:10 AM] [ INFO] import filename = epg123.mxf
[2/28/2017 2:00:32 AM] [ INFO] Successfully imported .mxf file into Media Center. Exit code: 0
[2/28/2017 2:00:33 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[2/28/2017 2:00:33 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[2/28/2017 2:00:33 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[2/28/2017 2:00:33 AM] [STATS] epg123Client mxf load and database reindex execution time was 00:00:24.1400000.
[2/28/2017 2:00:33 AM] ====================== Completed epg123 client execution. =====================

[DSperber]

Here's a successful SAVE + EXECUTE from EPG123.exe right now.

So what's the difference between the automatic overnight task that runs at 2AM?

Code: Select all

[2/28/2017 8:51:49 AM] ===============================================================================
[2/28/2017 8:51:49 AM]  Activating the epg123 configuration GUI.
[2/28/2017 8:51:49 AM] ===============================================================================
[2/28/2017 8:51:52 AM] [ INFO] epg123 is not up to date. Latest version is 1.1.2 and can be downloaded from http://epg123.garyan2.net.
[2/28/2017 8:51:52 AM] [ INFO] Successfully queried the Task Scheduler for status. status: Ready. Last Run 2/28/2017 2:00:00 AM; Exit: 0x00000000.
[2/28/2017 8:51:53 AM] [ INFO] Token request successful. serverID: 20141201.web.3
[2/28/2017 8:51:53 AM] [ INFO] Status request successful. account expires: 2017-04-21T07:19:18Z , lineups: 2/4 , lastDataUpdate: 2017-02-28T14:57:07Z
[2/28/2017 8:51:53 AM] [ INFO] system status: Online , message: No known issues.
[2/28/2017 8:51:53 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[2/28/2017 8:51:53 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-CA57315-X.
[2/28/2017 8:51:54 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-OTA-90292.
[2/28/2017 8:52:15 AM] ===============================================================================
[2/28/2017 8:52:15 AM]  Beginning epg123 update execution.
[2/28/2017 8:52:15 AM] ===============================================================================
[2/28/2017 8:52:15 AM] [ INFO] Successfully retrieved TMDb configurations.
[2/28/2017 8:52:15 AM] [ INFO] epg123 version 1.1.1 , DaysToDownload: 28 , PrefixEpisodeTitle: True , AppendEpisodeDesc: True , TMDbCoverArt: True , LogoOverride: True , AutoAddNew: True
[2/28/2017 8:52:15 AM] [ INFO] Token request successful. serverID: 20141201.web.3
[2/28/2017 8:52:15 AM] [ INFO] epg123 is not up to date. Latest version is 1.1.2 and can be downloaded from http://epg123.garyan2.net.
[2/28/2017 8:52:15 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[2/28/2017 8:52:15 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-CA57315-X.
[2/28/2017 8:52:16 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-OTA-90292.
[2/28/2017 8:52:16 AM] Entering getAllScheduleEntryMd5s() for 28 days on 83 stations.
[2/28/2017 8:52:18 AM] [ INFO] Successfully retrieved Md5s for 83 station's daily schedules.
[2/28/2017 8:52:19 AM] [ INFO] Successfully retrieved 83 station's daily schedules.
[2/28/2017 8:52:28 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[2/28/2017 8:52:28 AM] Entering buildAllProgramEntries() for 16625 programs.
[2/28/2017 8:53:08 AM] [ INFO] Successfully retrieved 1300 programs metadata.
[2/28/2017 8:53:12 AM] Exiting buildAllProgramEntries(). SUCCESS.
[2/28/2017 8:53:12 AM] Entering buildAllGenericSeriesInfoDescriptions() for 2278 series.
[2/28/2017 8:53:17 AM] [ INFO] Successfully retrieved 96 programs generic description metadata.
[2/28/2017 8:53:17 AM] Exiting buildAllGenericSeriesInfoDescriptions(). SUCCESS.
[2/28/2017 8:53:17 AM] Entering getAllMoviePosters() for 1794 movies.
[2/28/2017 8:53:18 AM] [ INFO] Successfully retrieved artwork info for 185 programs.
[2/28/2017 8:53:19 AM] [ INFO] TMDb catalog search for "Elopement" from 2010 found 1 results.
[2/28/2017 8:53:19 AM] [ INFO] TMDb catalog search for "Stage Fright" from 2017 found 1 results.
[2/28/2017 8:53:19 AM] [ INFO] TMDb catalog search for "River Raft Nightmare" from 2015 found 0 results.
[2/28/2017 8:53:19 AM] [ INFO] TMDb catalog search for "River Raft Nightmare" from 2016 found 0 results.
[2/28/2017 8:53:19 AM] [ INFO] TMDb catalog search for "River Raft Nightmare" from 2014 found 0 results.
[2/28/2017 8:53:19 AM] [ INFO] TMDb catalog search for "The Maid" from 2016 found 4 results.
[2/28/2017 8:53:20 AM] [ INFO] TMDb catalog search for "Bluebeard's Eighth Wife" from 1938 found 1 results.
[2/28/2017 8:53:20 AM] [ INFO] TMDb catalog search for "Tokyo Chorus" from 1931 found 1 results.
[2/28/2017 8:53:20 AM] [ INFO] TMDb catalog search for "Aventure Malgache" from 1944 found 1 results.
[2/28/2017 8:53:20 AM] [ INFO] TMDb catalog search for "Big Business" from 1924 found 1 results.
[2/28/2017 8:53:20 AM] Exiting getAllMoviePosters(). SUCCESS.
[2/28/2017 8:53:20 AM] Entering getAllSeriesImages() for 2278 series.
[2/28/2017 8:53:21 AM] [ INFO] Successfully retrieved artwork info for 500 programs.
[2/28/2017 8:53:23 AM] [ INFO] Successfully retrieved artwork info for 251 programs.
[2/28/2017 8:53:24 AM] Exiting getAllSeriesImages(). SUCCESS.
[2/28/2017 8:53:24 AM] Entering writeMxf().
[2/28/2017 8:53:24 AM] Exiting writeMxf(). SUCCESS.
[2/28/2017 8:53:24 AM] Entering writeImageArchive().
[2/28/2017 8:53:24 AM] Exiting writeImageArchive(). SUCCESS.
[2/28/2017 8:53:26 AM] [ INFO] 1985 files deleted from the cache directory during cleanup.
[2/28/2017 8:53:26 AM] [STATS] Generated .mxf file contains 83 services, 2278 series, 16625 programs, and 32829 people with 3995 image links.
[2/28/2017 8:53:26 AM] ====================== Beginning epg123 client execution. =====================
[2/28/2017 8:53:26 AM] [ INFO] Import=True , Match=True , NoLogo=False
[2/28/2017 8:53:26 AM] [ INFO] import filename = epg123.mxf
[2/28/2017 8:53:53 AM] [ INFO] Successfully imported .mxf file into Media Center. Exit code: 0
[2/28/2017 8:53:54 AM] [ INFO] Completed the automatch of lineup stations to tuner channels.
[2/28/2017 8:53:54 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[2/28/2017 8:53:54 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[2/28/2017 8:53:54 AM] [STATS] epg123Client mxf load and database reindex execution time was 00:00:28.0644002.
[2/28/2017 8:53:54 AM] ====================== Completed epg123 client execution. =====================
[2/28/2017 8:53:56 AM] [STATS] epg123 update execution time was 00:01:41.8212006.

[DSperber]

One more point... note that the log shows the previous night's 2AM update was supposedly successful, or at least the return code was x'0000'.

Obvoiusly last night's update was NOT SUCCESSFUL, so I don't understand why the new log which starts off showing the results of the prior scheduled task run shouldn't show the error return code which genuinely occurred, rather than x'0000' as if it were error-free. Clearly, there was a FATAL ERROR and the scheduled task did NOT run successfully.

[stuartm]

I'm not positive but I think that is the error you see if there is a EPG123 instance already logged in to SD. You can only have one login at a time. Are you running two different machines updating at the same time? Or possibly you have left a EPG123 session logged in somewhere?

[DSperber]

You're absolutely right! Makes good sense.

I still had my original HTPC set to update Guide nightly at its same 2:00AM as I set the new HTPC to do, not realizing it would cause a problem. I'm no longer using the old HTPC to make new recordings, but I still have it operational so that I can view-down the considerable copy-protected content that's on it and only viewable on that machine and its extenders. I left EPG123 running every night just so that the Guide on that machine would still be current should I look at it occasionally, even if I'm not doing any new recordings over there. Never occurred to me to have the two machines separated by a bit.

I've now changed the old HTPC to update at 01:30AM, leaving the new one to update at 02:00AM. We'll see what happens tonight.

Thank you for the tip.

[DSperber]

Indeed. Success tonight.

Many thanks for interpreting the error for me.

Case closed.