Failed to login after 10 tries, exiting.

[ghost]

Expected Behavior

Bot continues to run without issue.

Actual Behavior

After running for random amounts of time (usually on the order of a few hours), the bot exits with this being the final message logged to the console:

[API] Token has expired, attempting to log back in... [2016-08-13 21:27:49] Web UI action: Player Stats [API] Token has expired, attempting to log back in... [API] Failed to login after 10 tries, exiting.

FWIW, the first time I ever saw this happen was after the introduction of the random time delay between API calls.

Steps to Reproduce

Run the bot normally.

Other Information

OS: Windows 10 64-bit Git Commit: a55b907e494c6fd2509e28e90ee1c9c21d0cbc89

[niicojs]

We'll look into it, but the chance are quite hight that this is some kind of soft ban.

[ghost]

Thanks, though wasn't the random time delay feature added specifically to address the issue of soft bans? Also, if it were a soft ban, I don't think that I would get XP/items from PokeStops, which I am.

[wchill]

I doubt that this is a ban as banned accounts CAN login (even if permanently banned); the API will just return status code 3 for permanent bans.

Please run the bot with --debug switch and give us the output from when the login fails (stripping out any sensitive information, of course).

[ghost]

I truncated the logs, as there were thousands of lines similar to these that just repeated in large chunks before the bot stopped...

First came this (but repeated over and over). Notice the 14:09 timestamp... basically all these logs occurred within seconds of each other:

[2API] Token has expired, attempting to log back in...016-08-14 13:51:44,494 [ auth] [DEBUG] Session Ticket still valid for further 00:12:41 hours (1471197104495 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 13:51:52,029 [ auth] [DEBUG] Session Ticket still valid for further 00:12:34 hours (1471197112029 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 13:52:30,677 [ auth] [DEBUG] Session Ticket still valid for further 00:11:55 hours (1471197150678 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 13:52:32,112 [ auth] [DEBUG] Session Ticket still valid for further 00:11:53 hours (1471197152113 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 13:57:30,368 [ auth] [DEBUG] Session Ticket still valid for further 00:06:55 hours (1471197450369 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 14:02:30,490 [ auth] [DEBUG] Session Ticket still valid for further 00:01:55 hours (1471197750491 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 14:07:30,683 [ auth] [DEBUG] Removed expired Session Ticket (1471198050683 < 1471197866082) [API] Token has expired, attempting to log back in...2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,342 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,342 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,358 [ pgoapi] [DEBUG] Auth provider: ptc 2016-08-14 14:09:11,358 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,358 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,358 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,358 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,358 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,358 [ auth_ptc] [ INFO] PTC User Login for: xxxxxx 2016-08-14 14:09:11,388 [connectionpool] [ INFO] Starting new HTTPS connection (1): sso.pokemon.com 2016-08-14 14:09:11,388 [connectionpool] [ INFO] Starting new HTTPS connection (1): sso.pokemon.com 2016-08-14 14:09:11,388 [connectionpool] [ INFO] Starting new HTTPS connection (1): sso.pokemon.com 2016-08-14 14:09:11,388 [connectionpool] [ INFO] Starting new HTTPS connection (2): sso.pokemon.com 2016-08-14 14:09:11,388 [connectionpool] [ INFO] Starting new HTTPS connection (3): sso.pokemon.com 2016-08-14 14:09:11,388 [connectionpool] [ INFO] Starting new HTTPS connection (4): sso.pokemon.com 2016-08-14 14:09:11,404 [connectionpool] [ INFO] Starting new HTTPS connection (5): sso.pokemon.com 2016-08-14 14:09:11,404 [connectionpool] [ INFO] Starting new HTTPS connection (6): sso.pokemon.com 2016-08-14 14:09:12,154 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,154 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,168 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,168 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,168 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,168 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,184 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,335 [connectionpool] [DEBUG] "GET /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 200 104 2016-08-14 14:09:12,374 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,390 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,390 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,390 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,390 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,404 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,451 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,749 [connectionpool] [DEBUG] "POST /sso/login?service=https%3A%2F%2Fsso.pokemon.com%2Fsso%2Foauth2.0%2FcallbackAuthorize HTTP/1.1" 302 0 2016-08-14 14:09:12,749 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-25911351-nlzmcxAG1z2gCnl9docU-sso.pokemon.com HTTP/1.1" 500 None 2016-08-14 14:09:12,749 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-25970763-2dmVpXjszmc2oeQ7212s-sso.pokemon.com HTTP/1.1" 500 None 2016-08-14 14:09:12,749 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-26225475-INgIyVE73dKnJH02J4dK-sso.pokemon.com HTTP/1.1" 500 None 2016-08-14 14:09:12,765 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-26225038-z6QKJ3FYKiNwr3ZbbWR7-sso.pokemon.com HTTP/1.1" 500 None 2016-08-14 14:09:12,765 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-25979587-BsBqyYE2GGibB9yAgHXJ-sso.pokemon.com HTTP/1.1" 500 None 2016-08-14 14:09:12,765 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-25979589-phBFGQSrN9JXF7wxFRT1-sso.pokemon.com HTTP/1.1" 500 2565 2016-08-14 14:09:12,765 [connectionpool] [DEBUG] "GET /sso/oauth2.0/callbackAuthorize?ticket=ST-25979588-4uK5gM3Od3iUl2NSnbEt-sso.pokemon.com HTTP/1.1" 500 2565 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,765 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,765 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,765 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,765 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] Request PTC Access Token... 2016-08-14 14:09:12,765 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] Request PTC Access Token... 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] Request PTC Access Token... 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] Request PTC Access Token... 2016-08-14 14:09:12,765 [ auth_ptc] [ INFO] Request PTC Access Token... 2016-08-14 14:09:12,857 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,858 [ auth_ptc] [ INFO] PTC User Login successful. 2016-08-14 14:09:12,858 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,858 [ auth] [DEBUG] No Access Token available! 2016-08-14 14:09:12,858 [ auth_ptc] [ INFO] Request PTC Access Token... 2016-08-14 14:09:12,858 [ auth_ptc] [ INFO] Request PTC Access Token...

Then this at the end:

2016-08-14 14:09:29,477 [ rpc_api] [DEBUG] Decode raw over protoc (protoc has to be in your PATH): Couldn't find protoc in your environment OR other issue... 2016-08-14 14:09:29,477 [ rpc_api] [DEBUG] Parsing sub RPC responses... Exception in thread Thread-4029: Traceback (most recent call last): File "C:\Python27\lib\threading.py", line 801, in *bootstrap_inner self.run() File "C:\Python27\lib\threading.py", line 754, in run self.__target(_self.__args, _self.kwargs) File "C:\Python27\lib\site-packages\socketio\server.py", line 450, in _handle_eio_message self._handle_event(sid, pkt.namespace, pkt.id, pkt.data) File "C:\Python27\lib\site-packages\socketio\server.py", line 400, in _handle_event r = self._trigger_event(data[0], namespace, sid, _data[1:]) File "C:\Python27\lib\site-packages\socketio\server.py", line 426, in _trigger_event return self.handlers[namespace]event File "C:\Python27\lib\site-packages\flask_socketioinit*.py", line 197, in _handler ret = handler(args) File "C:\Users\xxxxxx\Documents\GitHub\OpenPoGoBot\plugins\socket\uievents.py", line 94, in client_ask_for_eggs_list inventory = bot.api_wrapper.call() File "C:\Users\xxxxxx\Documents\GitHub\OpenPoGoBot\apiinit.py", line 81, in call if self.login() is False: File "C:\Users\xxxxxx\Documents\GitHub\OpenPoGoBot\apiinit.py", line 37, in login return self._api.login(provider, username, password, app_simulation=True) File "c:\users\xxxxxx\documents\github\openpogobot\src\pgoapi\pgoapi\pgoapi.py", line 175, in login response = self.app_simulation_login() File "c:\users\xxxxxx\documents\github\openpogobot\src\pgoapi\pgoapi\pgoapi.py", line 152, in app_simulation_login response = request.call() File "c:\users\xxxxxx\documents\github\openpogobot\src\pgoapi\pgoapi\pgoapi.py", line 232, in call response = request.request(self._api_endpoint, self._req_method_list, self.get_position()) File "c:\users\xxxxxx\documents\github\openpogobot\src\pgoapi\pgoapi\rpc_api.py", line 137, in request raise ServerSideRequestThrottlingException("Request throttled by server... slow down man") ServerSideRequestThrottlingException: Request throttled by server... slow down man

2016-08-14 14:09:40,105 [ rpc_api] [DEBUG] Decode raw over protoc (protoc has to be in your PATH): Couldn't find protoc in your environment OR other issue... 2016-08-14 14:09:40,105 [ rpc_api] [DEBUG] Parsing sub RPC responses... 2016-08-14 14:09:40,105 [ rpc_api] [DEBUG] Parsing class: POGOProtos.Networking.Responses_pb2.GetPlayerResponse 2016-08-14 14:09:40,105 [ rpc_api] [DEBUG] Parsing class: POGOProtos.Networking.Responses_pb2.GetHatchedEggsResponse 2016-08-14 14:09:40,105 [ rpc_api] [DEBUG] Received Session Ticket valid for 00:30:01 hours (1471198180106 < 1471199981955) 2016-08-14 14:09:40,108 [ pgoapi] [ INFO] Cleanup of request! 2016-08-14 14:09:40,108 [ pgoapi] [ INFO] Finished RPC login sequence (app simulation) 2016-08-14 14:09:40,108 [ pgoapi] [ INFO] Login process completed 2016-08-14 14:09:40,108 [ auth] [DEBUG] Session Ticket still valid for further 00:30:01 hours (1471198180108 < 1471199981955)

At this point, the bot just stopped.

[wchill]

Hm, I'll need to think about this one.

[ghost]

Fun fact: after I gathered those logs, I restarted the bot only to find out I had been banned.

[wchill]

Yep, that'll probably do it.