Invalid Token Logging Query

[eophten]

This occurs every minute (on cron tick). What does it mean? How can it be resolved?

{"message":"POST /oauth/token HTTP/1.1 → 400 Bad Request 77","context":{"data":{"response":{"code":400,"phrase":"Bad Request","version":"1.1","res_header_content-length":"77","error_msg":"invalid_token"},"cache":{"status":"MISS"},"request":{"method":"POST","url":"https://login.eveonline.com/oauth/token","host":"login.eveonline.com","path":"/oauth/token","target":"/oauth/token","version":"1.1"},"stats":{"time":"0.359869"}},"tag":"warning"},"level":400,"level_name":"ERROR","channel":"api_esi_requests","datetime":{"date":"2019-11-30 19:10:02.476666","timezone_type":3,"timezone":"UTC"},"extra":{"path":"/cron/deleteLogData","ip":""}}

[exodus4d]

@eophten You get the error from esi_requests.log right? Could you please check sso.log for entries with (same timestamp)?

I get some these errors during EVE downtime in my logs too.

Mon, 09 Sep 2019 22:16:28 +0000 [127.0.0.1] Unable to get a valid "access_token. Array
Mon, 09 Sep 2019 22:16:28 +0000 [127.0.0.1] (
Mon, 09 Sep 2019 22:16:28 +0000 [127.0.0.1] [grant_type] => refresh_token
Mon, 09 Sep 2019 22:16:28 +0000 [127.0.0.1] [refresh_token] => y7HmDw1KLXIEDq9kwM_TJu0vbc_9eNG5abBZJk1QRY9zxiXXXXXXXXXXXXXXXXXXXXXXXX
Mon, 09 Sep 2019 22:16:28 +0000 [127.0.0.1] )

• Can you see if refresh_token´s are different or if it is always the same character (equal refresh tokens)
• Can you check DB column character.esiRefreshToken with the refresh_token from sso.log to identify the character. - What is his lastLogin timestamp?

Explanation:

PF has a cronjob deleteLogData() that runs every minute. Characters flagged as online (ingame == EVE client active) are checked periodically if they are still online.
This check seems to fail for one (or more) characters because the refresh_token PF seems to be invalid for CCP.

[eophten]

Yes. this log was generated in esi_request.log. I see 3 unique tokens in sso.log, one which is occurring every minute (3000+ occurrences and continuing). The other two only triggered once each.

Sun, 01 Dec 2019 16:32:02 +0000 Unable to get a valid "access_token. Array Sun, 01 Dec 2019 16:32:02 +0000 ( Sun, 01 Dec 2019 16:32:02 +0000 [grant_type] => refresh_token Sun, 01 Dec 2019 16:32:02 +0000 [refresh_token] => cTbDQO2NypLcZ_mPb4eEA28-3nVlpTc9JvbhDUIOiHED2fQNutvj_9T20OHMcg3vb5bA9bykXpTrN9FxnUv4DA Sun, 01 Dec 2019 16:32:02 +0000 )
Checking DB and will provide update when I have the information.

[eophten]

Last login timestamp for the character in question is 2019-09-04 22:04:50

[exodus4d]

rgr thanks! For a quick "fix" you can delte the row from table character_log table relating to the characterId with the refresh_token = "cTbDQO2NypLcZ_mP......".

For a proper fix, Ill change the PHP code in the next release.

What happened?

• The refresh_token seems to be invalid and is not accepted by ESI. AFAIK they don´t have any "expire" data, but they might expire if character switches Corp/Ally or was transferred to an other owner.
• The deleteLogData() cronjob frequently checks all "active" characters and updates their location (in case someone is ingame online but not in PF. This update failes for characters with "invalid" refresh_tokens.