Error in log file: SD API WebException Thrown

[artm]

SO, I have v0.9.2 running on two laptops, both timed to update at 4:00AM. One works fine, no issues. The other returns this error in the log file below.

When I run it manually, it works. What's going on? Can I not run two SD updates at the same time maybe?




[4/4/2016 4:00:00 AM] ===============================================================================
[4/4/2016 4:00:00 AM] Beginning epg123 update execution.
[4/4/2016 4:00:00 AM] ===============================================================================
[4/4/2016 4:00:00 AM] [ INFO] epg123 version 0.9.2 , DaysToDownload: 30 , PrefixEpisodeTitle: True , AutoImport: True , TMDbCoverArt: True , LogoOverride: False , Automatch: True
[4/4/2016 4:00:03 AM] [ INFO] Successfully retrieved TMDb configurations.
[4/4/2016 4:00:04 AM] [ INFO] Token request successful. serverID: 20141201.web.1
[4/4/2016 4:00:04 AM] [ERROR] epg123 is not recognized as an approved app from Schedules Direct. code: 1005 , message: Did not recognize the submitted client. , datetime: 2016-04-04T08:00:04Z
[4/4/2016 4:00:04 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[4/4/2016 4:00:05 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-MA20483-X.
[4/4/2016 4:00:05 AM] Entering getAllScheduleEntryMd5s() for 30 days on 503 stations.
[4/4/2016 4:00:24 AM] [ INFO] Successfully retrieved Md5s for 503 station's daily schedules.
[4/4/2016 4:00:29 AM] [ INFO] Successfully retrieved 395 station's daily schedules.
[4/4/2016 4:01:33 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[4/4/2016 4:01:33 AM] Entering buildAllProgramEntries() for 48294 programs.
[4/4/2016 4:02:49 AM] [ERROR] SD API WebException Thrown. Message: The remote server returned an error: (403) Forbidden. , Status: ProtocolError
[4/4/2016 4:02:49 AM] [ERROR] Unhandled exception occurred. Exiting.
[4/4/2016 4:02:49 AM] [ERROR] Did not receive a response from Schedules Direct for 435 programs metadata.
[4/4/2016 4:02:49 AM] Problem occurred during buildProgramEntries(). Exiting.
[4/4/2016 4:02:49 AM] Failed to create MXF file. Exiting.
[4/4/2016 4:02:49 AM] [STATS] epg123 execution time was 00:02:48.6102361.

[artm]

I ran a manual update from two systems and one failed again. Here are the log files, successful one first and failed one second.

Code: Select all

[4/4/2016 10:55:38 AM] ===============================================================================
[4/4/2016 10:55:38 AM]  Activating the epg123 configuration GUI.
[4/4/2016 10:55:38 AM] ===============================================================================
[4/4/2016 10:55:41 AM] [ERROR] epg123 is not recognized as an approved app from Schedules Direct. code: 1005 , message: Did not recognize the submitted client. , datetime: 2016-04-04T14:56:27Z
[4/4/2016 10:55:42 AM] [ INFO] Token request successful. serverID: 20141201.web.2
[4/4/2016 10:55:42 AM] [ INFO] Status request successful. account expires: 2016-04-05T22:33:30Z , lineups: 1/4 , lastDataUpdate: 2016-04-03T21:32:01Z
[4/4/2016 10:55:42 AM] [ INFO] system status: Online , message: No known issues.
[4/4/2016 10:55:43 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[4/4/2016 10:55:43 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-MA20483-X.
[4/4/2016 10:55:43 AM] [ INFO] Successfully queried the Task Scheduler for status. status: Ready. Last Run 4/4/2016 4:00:00 AM; Exit: 0x00000000
[4/4/2016 10:55:47 AM] ===============================================================================
[4/4/2016 10:55:47 AM]  Beginning epg123 update execution.
[4/4/2016 10:55:47 AM] ===============================================================================
[4/4/2016 10:55:47 AM] [ INFO] epg123 version 0.9.2 , DaysToDownload: 30 , PrefixEpisodeTitle: True , AutoImport: True , TMDbCoverArt: True , LogoOverride: False , Automatch: True
[4/4/2016 10:55:47 AM] [ INFO] Successfully retrieved TMDb configurations.
[4/4/2016 10:55:47 AM] [ INFO] Token request successful. serverID: 20141201.web.1
[4/4/2016 10:55:47 AM] [ERROR] epg123 is not recognized as an approved app from Schedules Direct. code: 1005 , message: Did not recognize the submitted client. , datetime: 2016-04-04T14:56:33Z
[4/4/2016 10:55:47 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[4/4/2016 10:55:47 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-MA20483-X.
[4/4/2016 10:55:47 AM] Entering getAllScheduleEntryMd5s() for 30 days on 503 stations.
[4/4/2016 10:55:52 AM] [ INFO] Successfully retrieved Md5s for 503 station's daily schedules.
[4/4/2016 10:57:42 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[4/4/2016 10:57:42 AM] Entering buildAllProgramEntries() for 48294 programs.
[4/4/2016 10:59:38 AM] Exiting buildAllProgramEntries(). SUCCESS.
[4/4/2016 10:59:38 AM] Entering buildAllGenericSeriesInfoDescriptions() for 9042 series.
[4/4/2016 10:59:44 AM] Exiting buildAllGenericSeriesInfoDescriptions(). SUCCESS.
[4/4/2016 10:59:44 AM] Entering getAllMoviePosters() for 5332 movies.
[4/4/2016 10:59:45 AM] Exiting getAllMoviePosters(). SUCCESS.
[4/4/2016 10:59:45 AM] Entering getAllSportsImages() for 1059 sports showings.
[4/4/2016 10:59:45 AM] [ INFO] Successfully retrieved artwork info for 45 programs.
[4/4/2016 10:59:45 AM] Exiting getAllSportsImages(). SUCCESS.
[4/4/2016 10:59:45 AM] Entering getAllSeriesImages() for 9042 series.
[4/4/2016 10:59:46 AM] [ INFO] Successfully retrieved artwork info for 500 programs.
[4/4/2016 10:59:46 AM] [ INFO] Successfully retrieved artwork info for 136 programs.
[4/4/2016 10:59:46 AM] Exiting getAllSeriesImages(). SUCCESS.
[4/4/2016 10:59:46 AM] Entering writeImageArchive().
[4/4/2016 10:59:46 AM] Exiting writeImageArchive(). SUCCESS.
[4/4/2016 10:59:46 AM] Entering writeMxf().
[4/4/2016 10:59:48 AM] Exiting writeMxf(). SUCCESS.
[4/4/2016 10:59:48 AM] [STATS] Generated .mxf file contains 503 services, 9042 series, 48294 programs, and 63040 people with 12850 image links.
[4/4/2016 11:04:54 AM] [ INFO] Successfully imported .mxf file into Media Center. Exit code: 0
[4/4/2016 11:04:54 AM] Beginning AutoMatch feature.
[4/4/2016 11:04:57 AM] Completed AutoMatch feature.
[4/4/2016 11:04:57 AM] [ INFO] Starting ehPrivJob.exe /DoReindexSearchRoot to index guide data.
[4/4/2016 11:08:40 AM] [ INFO] Successfully completed the ReindexSearchRoot task. Exit code: 0
[4/4/2016 11:08:40 AM] [ INFO] Beginning cache cleanup routine.
[4/4/2016 11:08:46 AM] [ INFO] 0 files deleted from the cache directory during cleanup.
[4/4/2016 11:08:46 AM] [STATS] epg123 execution time was 00:12:59.8417703.

Code: Select all

[4/4/2016 10:55:55 AM] ===============================================================================
[4/4/2016 10:55:55 AM]  Activating the epg123 configuration GUI.
[4/4/2016 10:55:55 AM] ===============================================================================
[4/4/2016 10:55:58 AM] [ERROR] epg123 is not recognized as an approved app from Schedules Direct. code: 1005 , message: Did not recognize the submitted client. , datetime: 2016-04-04T14:55:59Z
[4/4/2016 10:56:00 AM] [ INFO] Token request successful. serverID: 20141201.web.2
[4/4/2016 10:56:00 AM] [ INFO] Status request successful. account expires: 2016-04-05T22:33:30Z , lineups: 1/4 , lastDataUpdate: 2016-04-03T21:32:01Z
[4/4/2016 10:56:00 AM] [ INFO] system status: Online , message: No known issues.
[4/4/2016 10:56:00 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[4/4/2016 10:56:00 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-MA20483-X.
[4/4/2016 10:56:01 AM] [ INFO] Successfully queried the Task Scheduler for status. status: Ready. Last Run 4/4/2016 4:00:00 AM; Exit: 0x00000000
[4/4/2016 10:56:06 AM] ===============================================================================
[4/4/2016 10:56:06 AM]  Beginning epg123 update execution.
[4/4/2016 10:56:06 AM] ===============================================================================
[4/4/2016 10:56:06 AM] [ INFO] epg123 version 0.9.2 , DaysToDownload: 30 , PrefixEpisodeTitle: True , AutoImport: True , TMDbCoverArt: True , LogoOverride: False , Automatch: True
[4/4/2016 10:56:06 AM] [ INFO] Successfully retrieved TMDb configurations.
[4/4/2016 10:56:06 AM] [ INFO] Token request successful. serverID: 20141201.web.1
[4/4/2016 10:56:06 AM] [ERROR] epg123 is not recognized as an approved app from Schedules Direct. code: 1005 , message: Did not recognize the submitted client. , datetime: 2016-04-04T14:56:07Z
[4/4/2016 10:56:06 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[4/4/2016 10:56:06 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-MA20483-X.
[4/4/2016 10:56:06 AM] Entering getAllScheduleEntryMd5s() for 30 days on 503 stations.
[4/4/2016 10:56:13 AM] [ INFO] Successfully retrieved Md5s for 503 station's daily schedules.
[4/4/2016 10:56:31 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[4/4/2016 10:56:31 AM] Entering buildAllProgramEntries() for 48294 programs.
[4/4/2016 10:56:59 AM] [ERROR] SD API WebException Thrown. Message: The remote server returned an error: (403) Forbidden. , Status: ProtocolError
[4/4/2016 10:56:59 AM] [ERROR] Unhandled exception occurred. Exiting.
[4/4/2016 10:56:59 AM] [ERROR] Did not receive a response from Schedules Direct for 435 programs metadata.
[4/4/2016 10:56:59 AM] Problem occurred during buildProgramEntries(). Exiting.
[4/4/2016 10:56:59 AM] Failed to create MXF file. Exiting.
[4/4/2016 10:56:59 AM] [STATS] epg123 execution time was 00:00:53.8720813.

[garyan2]

This problem is on the server side and I haven't been able to capture exactly what is going on. The server is supposed to respond with a status code and description of what happened, but ends up just throwing the 403 error. I was getting these errors last night when requesting lineups which lasted about 2 minutes and then was fine.

Could be I am violating some kind of server side requirements to limit the time between requests. I'll get with Schedules Direct later to try and determine the cause.

[rkulagow]

Part of the status response indicates which server handled the request (web.1, .2, etc); I would need to know that in order to check the logs.

[glorp]

His successful run says it initially connected to web.1. The failed run says web.2. I assume the connections are persistent from the login connection. It's shown at the top of each log run.

[artm]

I hope I was clear...the two runs above were run at the same time from two separate PC's. The first system succeeded, the second failed. Running the second system on its own shortly after the failed run, succeeded.

[rkulagow]

An account can only have one token outstanding; if you ran both at the same exact time, then at some point the token would have been overwritten, so the "second" instance would have had an invalid token at that point.

[artm]

OK, that's what I thought was going on.

So, it would be a good feature to add to EPG123...see if this error occurs and wait for the first update to end before continuing.

Otherwise, I can run them separately and assume the first run ended before starting the second. Obviously, that can fail as well.

[rkulagow]

@garyan2:

All of my code returns a reason why the client got a 403, so if you look at the body of the response you would get JSON and you can use that to see what happened and can add that to your log.

[garyan2]

Now added that in my WebException error handling...didn't realize the information was there. If anything, I'm going to have a pretty solid SD API for windows when I'm done.

[artm]

So, I ran the two systems 2 hours apart and they both succeeded.

Even if they did not, it's no big deal to wait one more day for a successful update.

Still, I would like to see it addressed in EPG123.

Well?

[garyan2]

So, I ran the two systems 2 hours apart and they both succeeded.

Even if they did not, it's no big deal to wait one more day for a successful update.

Still, I would like to see it addressed in EPG123.

Well?

Um, no. There is nothing I can do in epg123 to determine 1) if there is already an outstanding token from another system, or 2) if that system is still using said token. You're just going to have to live within the limitations of epg123 and the SD API and either construct a Whole Home Configuration or stagger your updates.

[artm]

Oh, I misunderstood...I thought SD said that the error returned also specifies a code as to why. If that code is specific and says token already in use, for example, then EPG123 can wait and do a retry. If the error code is unspecific then so be it. Sounds like it should be implemented by SD if it is not.

I did see that other thread on whole house config. In the end that's more efficient on resources so I'll try it.

[garyan2]

Nope, not that specific and the SD server really doesn't know. A token is granted upon successful account login/request and is valid for 24 hours. There is no checking the token back in or releasing it so as far as SD is concerned, the client will use the same token on any machine as much as they want within the next 24 hours. Requesting a new token will invalidate the previous token and the counter starts again.

EDIT: the SD server response would probably be code: 4006, "Token has expired. Request new token."

[texasex1998]

I too have this error, I am just testing SD so I thought I needed to try to setup a new account, that did the same thing. I am baffled.

[artm]

So, you're running multiple updates at the same time, correct?

I staggered my updates between the two systems two hours apart and no more errors.

[texasex1998]

No only one, when it first threw the error I thought something was wrong with my account so I tried setting up another which gave the same error

[garyan2]

If you are still having this problem, I can post the next release tonight which will give a much more detailed description of the problem provided by SD.

[texasex1998]

Thanks I was still having it this afternoon

[garyan2]

Thanks I was still having it this afternoon

And just to verify...what is the error?