request_logs GAE authentication stopped working

[Julian Bunn]

We have a process that uses the request_logs feature to download logs from our GAE app for archival. This has stopped working unexpectedly in the last couple of days, apparently due to an oauth2 authentication issue. I'm not sure if this is a problem at our end, or on the GAE side, and I'm struggling to debug it.

My understanding is that when the oauth2 token has expired, it is refreshed automatically, but that process appears to fail.

Here is what the logs downloader process log shows:

python2.7 request_logs.py

2017-03-24 08:55:05,739 INFO     root        : Recovered sentinel with timestamp: 2017-03-22 09:39:59-07:00

08:55 AM Host: appengine.google.com

08:55 AM Downloading request logs for app my-gae-service version 4.

2017-03-24 08:55:05,757 INFO     root        : Request with offset None.

2017-03-24 08:55:05,757 INFO     oauth2client.client: access_token is expired. Now: 2017-03-24 15:55:05.757671, token_expiry: 2017-03-23 23:54:13

2017-03-24 08:55:05,757 DEBUG    google.appengine.tools.appengine_rpc: _Authenticate skipped auth; needs_auth=False

2017-03-24 08:55:05,757 DEBUG    google.appengine.tools.appengine_rpc: Sending request to https://appengine.google.com/api/request_logs?app_id=my-gae-service&include_all=True&include_vhost=False&limit=1000&no_header=1&severity=1&version=4 headers={'X-appcfg-api-version': '1'} body=

2017-03-24 08:55:05,890 DEBUG    google.appengine.tools.appengine_rpc: Got http error 401.

2017-03-24 08:55:05,890 DEBUG    google.appengine.tools.appengine_rpc: Attempting to auth. This is try 1 of 3.

2017-03-24 08:55:05,890 INFO     oauth2client.client: access_token is expired. Now: 2017-03-24 15:55:05.890322, token_expiry: 2017-03-23 23:54:13

2017-03-24 08:55:05,890 DEBUG    google.appengine.tools.appengine_rpc: _Authenticate configuring auth; needs_auth=True

2017-03-24 08:55:05,890 DEBUG    google.appengine.tools.appengine_rpc: Sending request to https://appengine.google.com/api/request_logs?app_id=my-gae-service&include_all=True&include_vhost=False&limit=1000&no_header=1&severity=1&version=4 headers={'X-appcfg-api-version': '1'} body=

2017-03-24 08:55:05,974 INFO     oauth2client.client: Refreshing due to a 401 (attempt 1/2)

2017-03-24 08:55:05,975 INFO     oauth2client.client: Refreshing access_token

2017-03-24 08:55:08,761 DEBUG    google.appengine.tools.appengine_rpc: Got http error 500.

2017-03-24 08:55:08,761 DEBUG    google.appengine.tools.appengine_rpc: Retrying. This is attempt 1 of 3.

2017-03-24 08:55:08,761 DEBUG    google.appengine.tools.appengine_rpc: _Authenticate configuring auth; needs_auth=True

2017-03-24 08:55:08,761 DEBUG    google.appengine.tools.appengine_rpc: Sending request to https://appengine.google.com/api/request_logs?app_id=my-gae-service&include_all=True&include_vhost=False&limit=1000&no_header=1&severity=1&version=4 headers={'X-appcfg-api-version': '1'} body=

2017-03-24 08:55:09,644 DEBUG    google.appengine.tools.appengine_rpc: Got http error 500.

2017-03-24 08:55:09,644 DEBUG    google.appengine.tools.appengine_rpc: Retrying. This is attempt 2 of 3.

2017-03-24 08:55:09,644 DEBUG    google.appengine.tools.appengine_rpc: _Authenticate configuring auth; needs_auth=True

2017-03-24 08:55:09,644 DEBUG    google.appengine.tools.appengine_rpc: Sending request to https://appengine.google.com/api/request_logs?app_id=my-gae-service&include_all=True&include_vhost=False&limit=1000&no_header=1&severity=1&version=4 headers={'X-appcfg-api-version': '1'} body=

2017-03-24 08:55:10,598 DEBUG    google.appengine.tools.appengine_rpc: Got http error 500.

2017-03-24 08:55:10,598 DEBUG    google.appengine.tools.appengine_rpc: Retrying. This is attempt 3 of 3.

2017-03-24 08:55:10,598 INFO     root        : Too many retries for url https://appengine.google.com/api/request_logs?app_id=my-gae-service&include_all=True&include_vhost=False&limit=1000&no_header=1&severity=1&version=4

Error 500: --- begin server output ---

 

 

Server Error (500)

 

A server error has occurred.

--- end server output ---

2017-03-24 08:55:10,599 INFO     root        : Downloaded 0 logs

Does anyone have any idea what may be wrong here? 

Thanks!

[Nick (Cloud Platform Support)]

Hey Julian,

What version of the SDK are you using? And is this still occurring?

Cheers,

Nick
Cloud Platform Community Support

[Julian Bunn]

Hi Nick!

It's still occurring as of one minute ago ... using release 1.9.50

Julian

[Staffan Rolfsson]

Hi, I got problems to deploy on 1.9.51 (updated from 1.9.48),
and after some googling I found that it was due to expired certificates.
Could this be a similiar problem?
It was easy to fix on your own (as we wait for official fix?),
- in SDK choose menu>> File>> Open SDK in explorer

- open lib/cacerts folder

- rename urlfetch_cacerts.txt to urlfetch_cacerts.old.txt

- rename caccerts.txt to  urlfetch_cacerts.txt 

- try again
:)
/Staffan

[Julian Bunn]

Hi Staffan,

Thanks for this suggestion - I tried it, but it didn't appear to make any difference. Can you tell me where you saw this issue of expired certificates talked out?

It looks to me as if there is something wrong with the oauth2 handling of the token refresh from request_logs on the Google servers? I'm wondering if it's related to the fact we don't use StackDriver logging, and the push seems to be towards that?

Julian

[Edward Grech]

It has been reported here: https://issuetracker.google.com/u/1/issues/36637246