Failed to check in due to local time being ahead #235

aaron-pham · 2024-03-04T05:31:03Z

Version

7.2

Browser Version

121.0.6167.189

Description

Hey, was mainly using this app to track prices, but noticed I had a failed check-in. Any idea what went on? The price check component was working flawlessly.

The logs are attached below.

To Reproduce

Fill in config.json with reservations
Run python southwest.py --verbose
Let it run & check in

Expected Behavior

Check-in is successful.

Relevant logs and program output

2024-03-03 08:44:55 DEBUG Process-4:1[checkin_handler:124]: Attempting to check in
Checking in to flight from 'Sacramento' to 'Honolulu (Oahu)' for Mickey Ly

2024-03-03 08:44:55 DEBUG Process-4:1[checkin_handler:138]: Making GET request to check in
2024-03-03 08:45:30 DEBUG Process-4:1[checkin_handler:147]: Failed to check in. Error: Bad Request 400. Exiting
2024-03-03 08:45:30 DEBUG Process-4:1[notification_handler:111]: Sending failed check-in notification...
Failed to check in to flight [REDACTED] for Mickey Ly. Reason: Bad Request 400.
Check in at this url: https://mobile.southwest.com/check-in

Additional context

No response

aaron-pham · 2024-03-04T05:43:26Z

Hmmm, I reran the bot and it actually succeeded the next time. Wonder if there should be some retry mechanism?

jdholtz · 2024-03-04T16:59:51Z

Hey, thanks for filing this issue. Someone else also reached this issue here. A Bad Request 400 means that there was a client-side error, but I'm not really sure what went wrong because it worked when you ran it again. Perhaps it is something on Southwest's side or has to do with #230 (although this isn't with Docker).

Wonder if there should be some retry mechanism?

The check-in will try 20 times (with the logs, you can see it took 35 seconds to fail) when it encounters an unsuccessful request but its unclear why the issue is not reproducible when you restart the script.

aaron-pham · 2024-03-05T02:00:34Z

any ideas for logging to help debug the issue? I have some more flights coming up in 2 weeks.

jdholtz · 2024-03-05T02:53:04Z

Could you send the log of the run that failed (in the logs/ folder)? There should be more output in between Making GET request to check in and the Bad Request 400 which logs the response body it received when it failed and I'm not sure why that didn't show up.

aaron-pham · 2024-03-05T03:19:41Z

Hmm this is all I see in those logs:

2024-03-03 08:14:55 DEBUG Process-4:1[checkin_handler:94]: Acquiring lock...
2024-03-03 08:14:55 DEBUG Process-4:1[checkin_handler:96]: Lock acquired
2024-03-03 08:14:55 DEBUG Process-4:1[checkin_scheduler:50]: Refreshing headers for current session
2024-03-03 08:14:55 DEBUG Process-4:1[webdriver:106]: Starting webdriver for current session
2024-03-03 08:15:01 DEBUG Process-4:1[webdriver:122]: Using browser version: 121.0.6167.189
2024-03-03 08:15:01 DEBUG Process-4:1[webdriver:126]: Loading Southwest Check-In page
2024-03-03 08:15:07 DEBUG Process-4:1[webdriver:64]: Waiting for valid headers
2024-03-03 08:15:07 DEBUG Process-4:1[webdriver:155]: Waiting for headers_set to be set
2024-03-03 08:15:08 DEBUG Process-4:1[webdriver:159]: headers_set set successfully
2024-03-03 08:15:10 DEBUG Process-4:1[checkin_handler:99]: Lock released
2024-03-03 08:15:10 DEBUG Process-4:1[checkin_handler:103]: Sleeping until check-in: 1784 seconds...
2024-03-03 08:44:55 DEBUG Process-4:1[checkin_handler:124]: Attempting to check in
2024-03-03 08:44:55 DEBUG Process-4:1[checkin_handler:138]: Making GET request to check in
2024-03-03 08:45:30 DEBUG Process-4:1[checkin_handler:147]: Failed to check in. Error: Bad Request 400. Exiting
2024-03-03 08:45:30 DEBUG Process-4:1[notification_handler:111]: Sending failed check-in notification...

jdholtz · 2024-03-05T03:22:22Z

What operating system are you on?

aaron-pham · 2024-03-05T03:36:41Z

windows 11 pro

Version 10.0.22621 Build 22621

jdholtz · 2024-03-05T05:24:38Z

Ah, the module that logs the requests was not updated when I fixed logging on Windows, so it hasn't been logging this whole time on Windows...ha. Well, that will be fixed in v7.3. If you (or someone else) gets this issue again, the debug output should be a lot more helpful.

aaron-pham · 2024-03-05T18:43:16Z

Haha, well glad we helped find a "bug"! I'll update to 7.3 and let you know how it goes in a few weeks.

Malklor · 2024-03-05T19:14:13Z

I am having a very similar issue

Here is my dump from the log file

Logs

2024-03-05 19:10:52 DEBUG MainProcess[log:23]: Initialized the application
2024-03-05 19:10:52 DEBUG MainProcess[main:105]: Auto-Southwest Check-In v7.3
2024-03-05 19:10:52 DEBUG MainProcess[main:66]: Called with 0 arguments
2024-03-05 19:10:52 DEBUG MainProcess[config:132]: Initializing configuration file
2024-03-05 19:10:52 DEBUG MainProcess[config:161]: Reading the configuration file
2024-03-05 19:10:52 DEBUG MainProcess[config:174]: Reading configuration from environment variables
2024-03-05 19:10:52 DEBUG MainProcess[config:60]: Setting check fares to True
2024-03-05 19:10:52 DEBUG MainProcess[config:75]: Setting retrieval interval to 24 hours
2024-03-05 19:10:52 DEBUG MainProcess[config:109]: Setting notification level to <NotificationLevel.INFO: 1>
2024-03-05 19:10:52 DEBUG MainProcess[config:122]: Using 1 notification services
2024-03-05 19:10:52 DEBUG MainProcess[config:144]: Creating configurations for 1 accounts
2024-03-05 19:10:52 DEBUG MainProcess[config:151]: Creating configurations for 0 reservations
2024-03-05 19:10:52 DEBUG MainProcess[main:90]: Monitoring 1 accounts and 0 reservations
2024-03-05 19:10:52 DEBUG Process-1[reservation_monitor:168]: Acquiring lock...
2024-03-05 19:10:52 DEBUG Process-1[reservation_monitor:170]: Lock acquired
2024-03-05 19:10:52 DEBUG Process-1[reservation_monitor:192]: Retrieving reservations for account
2024-03-05 19:10:52 DEBUG Process-1[webdriver:106]: Starting webdriver for current session
2024-03-05 19:10:53 DEBUG Process-1[webdriver:122]: Using browser version: 122.0.6261.94
2024-03-05 19:10:53 DEBUG Process-1[webdriver:126]: Loading Southwest Check-In page
2024-03-05 19:10:56 DEBUG Process-1[webdriver:79]: Logging into account to get a list of reservations and valid headers
2024-03-05 19:10:57 DEBUG Process-1[webdriver:155]: Waiting for headers_set to be set
2024-03-05 19:10:57 DEBUG Process-1[webdriver:159]: headers_set set successfully
2024-03-05 19:10:59 DEBUG Process-1[webdriver:155]: Waiting for login_request_id to be set
2024-03-05 19:10:59 DEBUG Process-1[webdriver:147]: Login response has been received
2024-03-05 19:10:59 DEBUG Process-1[webdriver:159]: login_request_id set successfully
2024-03-05 19:10:59 DEBUG Process-1[webdriver:233]: First time logging in. Setting account name
2024-03-05 19:10:59 DEBUG Process-1[webdriver:155]: Waiting for trips_request_id to be set
2024-03-05 19:11:00 DEBUG Process-1[webdriver:151]: Upcoming trips response has been received
2024-03-05 19:11:00 DEBUG Process-1[webdriver:159]: trips_request_id set successfully
2024-03-05 19:11:00 DEBUG Process-1[reservation_monitor:211]: Successfully retrieved 2 reservations
2024-03-05 19:11:00 DEBUG Process-1[reservation_monitor:86]: Scheduling flight check-ins for 2 reservations
2024-03-05 19:11:00 DEBUG Process-1[checkin_scheduler:76]: Retrieving reservation information
2024-03-05 19:11:16 DEBUG Process-1[utils:40]: Failed to make request after 20 attempts: Forbidden 403
2024-03-05 19:11:16 DEBUG Process-1[utils:43]: Response body: {
"code": 403050700
}
2024-03-05 19:11:16 DEBUG Process-1[checkin_scheduler:82]: Failed to retrieve reservation info. Error: Forbidden 403. Exiting
2024-03-05 19:11:16 DEBUG Process-1[notification_handler:78]: Sending failed reservation retrieval notification...
2024-03-05 19:11:17 DEBUG Process-1[checkin_scheduler:57]: 0 flights found under current reservation
2024-03-05 19:11:17 DEBUG Process-1[checkin_scheduler:76]: Retrieving reservation information

this was working for me too then suddenly stop. I upgrade to latest version to see if it would resolve the issue.

jdholtz · 2024-03-05T20:23:06Z

@Malklor the issue you are facing is #230 (even if you aren’t using Docker). This issue is about receiving a Bad Request 400 during check-in.

aaron-pham · 2024-03-21T15:48:04Z

I think I found the reason. My windows time was not synced. About 1 minute off. Think this isn't an issue and was due to environment. Kind of silly windows doesn't have an option to stay in-sync for time, lol.

jdholtz · 2024-03-22T07:13:30Z

I think I found the reason. My windows time was not synced. About 1 minute off. Think this isn't an issue and was due to environment.

That would explain the 400 status code. If the logging was working at this time, it probably would have shown “too early to check in”.

Do you want to close this issue as a user error or do you have an idea of a programmatic way of solving it? One option could be to communicate with an external time server, but that seems overkill. Detecting that it’s too early won’t do much too because, if the time is wrong, the script won’t know how off the time is.

jdholtz · 2024-04-18T20:42:25Z

Hey @aaron-pham, do you have any thoughts on my reply above?

aaron-pham · 2024-04-18T21:35:07Z

I kind of like checking the timeserver for our time - we're already making network calls and whatnot. It would be a nice layer of protection but possibly adds some complexity. I'm pretty busy right now - so maybe we can close this and perhaps look into this another time.

A basic thing would be checking & logging it which could help with debugging, but as you said the 400s would probably give you an idea. It would be slightly hard to track down without explicit logs still since they would show the "proper" time.

jdholtz · 2024-04-19T01:27:56Z

I have a working implementation of using an NTP server (and falling back to getting the system’s local time on error) on my local machine. It actually is very simple to implement because the ntplib package can be used for the bulk of the actual request and parsing.

I’ll implement it on another branch so it can be tested in action. This feature may also help fix #252.

Fixes #235. Instead of relying on the computer's local time (which may be off), the time is fetched from an NTP server when possible. This ensures the script performs check-ins at the correct times even when the local time is incorrect.

jdholtz · 2024-04-20T01:10:42Z

I decided to merge this into the develop branch as I was able to test it (not a check-in, but the NTP fetch is used in other places so I tested through that). Thanks for the suggestion @aaron-pham. This should fix the issue you received in future check-ins.

Fixes jdholtz#235. Instead of relying on the computer's local time (which may be off), the time is fetched from an NTP server when possible. This ensures the script performs check-ins at the correct times even when the local time is incorrect.

aaron-pham added the bug Something isn't working label Mar 4, 2024

jdholtz mentioned this issue Mar 4, 2024

Failing to login: Reason: Invalid credentials. Status code: 400. #223

Closed

jdholtz changed the title ~~Failed to check in~~ Failed to check in. Bad Request 400 Mar 4, 2024

jdholtz mentioned this issue Apr 20, 2024

Use an NTP server to fetch the current time #255

Merged

jdholtz closed this as completed Apr 20, 2024

jdholtz changed the title ~~Failed to check in. Bad Request 400~~ Failed to check in due to local time being ahead Apr 20, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Failed to check in due to local time being ahead #235

Failed to check in due to local time being ahead #235

aaron-pham commented Mar 4, 2024

aaron-pham commented Mar 4, 2024

jdholtz commented Mar 4, 2024

aaron-pham commented Mar 5, 2024

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 5, 2024

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 5, 2024

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 5, 2024

Malklor commented Mar 5, 2024 •

edited by jdholtz

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 21, 2024

jdholtz commented Mar 22, 2024

jdholtz commented Apr 18, 2024

aaron-pham commented Apr 18, 2024

jdholtz commented Apr 19, 2024

jdholtz commented Apr 20, 2024

Failed to check in due to local time being ahead #235

Failed to check in due to local time being ahead #235

Comments

aaron-pham commented Mar 4, 2024

Version

Browser Version

Description

To Reproduce

Expected Behavior

Relevant logs and program output

Additional context

aaron-pham commented Mar 4, 2024

jdholtz commented Mar 4, 2024

aaron-pham commented Mar 5, 2024

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 5, 2024

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 5, 2024

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 5, 2024

Malklor commented Mar 5, 2024 • edited by jdholtz

jdholtz commented Mar 5, 2024

aaron-pham commented Mar 21, 2024

jdholtz commented Mar 22, 2024

jdholtz commented Apr 18, 2024

aaron-pham commented Apr 18, 2024

jdholtz commented Apr 19, 2024

jdholtz commented Apr 20, 2024

Malklor commented Mar 5, 2024 •

edited by jdholtz