[TLDR? Fix is at bottom of page.]
We just spent two days debugging a problem with our google adwords API keys and finally got things working. We’re not sure if this problem is affecting people globally, but it was particularly difficult to debug so I wanted to get this information out there. Let me know if it helped you out.
We’ve been using API keys to generate google ads for several years
now. If you’re using them, you have a basic understanding of how
things work in ruby-land. There is a configuration file adwords_api.yml
that you
set up with basic values, then run the setup_oauth2.rb
script
included in the github repository for Google’s gems. This has you do
browser-based authentication, and then the file will have a refresh
token. When this file is re-used, the refresh token is used to request
an access token as needed, and this access token is used to generate
ads.
Yesterday morning, things blew up horribly and all of our processes generating ads failed! We went into major fire-fighting mode did some basic debugging. We decided that a three year old refresh token might be the problem, and regenerated one locally, and things seemed to be working again. But then, after an hour, all our processes would blow up again. We could fix the tokens every hour, but this obviously wasn’t a full-time solution.
As we tracked things down and went through many red herrings, we came
to realize that normally Google’s code would figure out that the
current access token was expired, and would request a new one via the refresh
token. As we dug in to the google code, we finally made our way to the
oauth2_handler.rb file in ads_common. In
particular the get_token
method on line 89:
# Overrides base get_token method to account for the token expiration.
def get_token(credentials = nil, force_refresh = false)
token = super(credentials)
token = refresh_token! if !@client.nil? &&
(force_refresh || @client.expired?)
return token
end
Using bundle open google-ads-common
we were able to go in and change
force_refresh
to default to true. Lo and behold, authentication was
working! So forcing the creation of a new token solved the immediate
problem, but we still wanted to have a better idea of what was
happening, and we were reluctant to monkey-patch Google’s gem only to
have things break in future versions.
There was one interesting thing we noticed as we looked through
various SOAP output. Getting back to the original inputs, there are
two values attached to the access token, the creation date, and the
time, in seconds, until it expires. As we looked at the output, we
noticed that it was returning expires_in
values that were actually
counterintuitively increasing rather than decreasing. We would have
expected a key that started at 3600 to, when called a minute later, to
return 3540. Instead it was returning 3660, and climbing up until
hitting 7200 one hour later, at which point the access token would be
expired, but our code would not generate a fresh token, and our app would
start blowing up.
Unfortunately, we were unable to tell if the value always worked this way, or if there was a new breaking change introduced yesterday morning when we first encountered errors.
We were reluctant to monkey-patch the core google libraries and have to deal with that. So armed with the knowledge that our gems weren’t calculating expiration date correctly, and we wanted them to know that they needed to generate the access token, we tried modifying our config files and found a fix that worked without having to patch google’s gems.
Original adwords_api.yml, as generated from setup_oauth2.rb
:
---
:authentication:
:method: OAuth2
:oauth2_client_id: REDACTED
:oauth2_client_secret: REDACTED
:developer_token: REDACTED
:client_customer_id: REDACTED
:user_agent: WebKite_Radius
:oauth2_token:
:access_token: REDACTED
:refresh_token: REDACTED
:issued_at: 2018-08-23 13:10:13.299601000 -04:00
:expires_in: 3600
:id_token:
:service:
:environment: PRODUCTION
:connection:
:enable_gzip: false
:library:
:log_level: INFO
Note the pertinent information is the :issued_at:
and :expires_in:
The fix is to switch :expires_in:
to 0:
---
:authentication:
:method: OAuth2
:oauth2_client_id: REDACTED
:oauth2_client_secret: REDACTED
:developer_token: REDACTED
:client_customer_id: REDACTED
:user_agent: WebKite_Radius
:oauth2_token:
:access_token: REDACTED
:refresh_token: REDACTED
:issued_at: 2018-08-23 13:10:13.299601000 -04:00
:expires_in: 0
:id_token:
:service:
:environment: PRODUCTION
:connection:
:enable_gzip: false
:library:
:log_level: INFO
After that, things worked perfectly! The gems assumed the current access_token was already expired since it had a lifetime of 0, and it forced generation of an up-to-date access key.
This was a really unusual bug for us, and we were surprised that it wasn’t all over StackOverflow or the Google forums since it completely took our production services down and was extremely difficult to resolve.
I’m still curious if we just have something really odd going on in our local setup, or if this was a more widespread problem. So please shoot me an email if you found this information helpful, or if you can shed any additional light on the sudden change in our production environment.
Thanks!
-Grant