Refreshing OAuth session does not work

[danwoolley]

I have never seen refreshing an oauth token actually work. Tokens expire and require the agent to enter credentials to get fresh tokens. This is bad for us because we want to get fresh listing data on behalf of agents automatically in the background, without their direct involvement. We're hoping that the use of refresh tokens can do this.

I've got sample code now that actually shows the refresh process failing. The root of the issue seems to be when the gem calls to create a session to https://sparkapi.com/v1/oauth2/grant with the param "grant_type" set to "refresh_token". The response is {"error"=>"invalid_grant", "error_description"=>"The access grant you supplied is invalid"}.

Attached is a ruby script using the latest gem v1.4.14 that shows the issue. It's based on script/combined_flow_example.rb, but with the added twist of forcing the tokens to expire so that we can attempt a refresh.

The best way to run this is from irb by pasting in one SECTION at a time. This allows you to see the debug logging. Recognize that you need to paste your key, secret, and callback on lines 8-10, and a valid client.oauth2_provider.code in on line 27.

Let me know if I'm not understanding how refresh tokens work, or if there's a better path through the code that does cause it to work.

Log output for me showing the exact error: D, [2017-07-06T12:15:07.895235 #54093] DEBUG -- : [oauth2] setup SparkApi::Authentication::OAuth2Impl::GrantTypeCode D, [2017-07-06T12:15:07.895297 #54093] DEBUG -- : [oauth2] Refresh oauth session. D, [2017-07-06T12:15:07.895330 #54093] DEBUG -- : [oauth2] Refreshing authentication to https://sparkapi.com/v1/oauth2/grant using [cbg4cv1goko1sahh9u4szzmkf] D, [2017-07-06T12:15:07.895399 #54093] DEBUG -- : [oauth2] create_session to https://sparkapi.com/v1/oauth2/grant params {"redirect_uri":"https://cloudcma.dev/spark/callback","client_id":"xxx","client_secret":"yyy","grant_type":"refresh_token","refresh_token":"cbg4cv1goko1sahh9u4szzmkf"} D, [2017-07-06T12:15:08.425257 #54093] DEBUG -- : [oauth2] Response Body: {"error"=>"invalid_grant", "error_description"=>"The access grant you supplied is invalid"}

spark_refresh.rb.txt

[danwoolley]

General question related to above: Should the refresh work on recently expired tokens? Or am I expected to proactively refresh all tokens before they expire?

[wlmcewen]

Hi @danwoolley, it's been a while since I've dug into this part of the code, but the code that checks for a refresh seems suspicious. If I recall correctly, a request must be made using the refresh token in the window after the refresh_timeout but before the expires_in.

In any case, we'll have our support team try to reproduce. I'll suggest you go ahead and remove your client_id/secret from this issue.

[ridley-james]

Hi @danwoolley,

My testing thus far has shown this to be working properly. One thing I noticed in you script is the deletion of the oauth2 token:

client.delete "/oauth2/token/#{client.session.access_token}"

What this does is delete the authorization completely, making the access/refresh tokens non-usable, resulting in all the resulting invalid grant types.

I approached it a little differently. Keeping the same basic structure of the beginning of your script I changed the delete portion to reset the expire_time to 60 (anything less then the refresh interval will work). From there you can see the refresh occur from the debugging:

SparkApi:044:0> client.session.expires_in = 60 60 SparkApi:046:0> client.session.expired? true SparkApi:047:0> puts "System metadata: #{client.get '/system'}" D, [2017-08-15T14:13:52.605581 #2340] DEBUG -- : [oauth2] setup SparkApi::Authentication::OAuth2Impl::GrantTypeCode D, [2017-08-15T14:13:52.605701 #2340] DEBUG -- : [oauth2] Refresh oauth session. D, [2017-08-15T14:13:52.605773 #2340] DEBUG -- : [oauth2] Refreshing authentication to https://sparkapi.com/v1/oauth2/grant using [9ws25a4ver5iae29crf01hjz8] D, [2017-08-15T14:13:52.605867 #2340] DEBUG -- : [oauth2] create_session to https://sparkapi.com/v1/oauth2/grant params {"redirect_uri":"http://frink.fbsdata.com/~jridley/php/callback.php","client_id":"********","client_secret":"********","grant_type":"refresh_token","refresh_token":"9ws25a4ver5iae29crf01hjz8"} D, [2017-08-15T14:13:52.839408 #2340] DEBUG -- : [oauth2] Response Body: {"access_token"=>"a9741naj3hbe64e8832aco48e", "expires_in"=>86400, "refresh_token"=>"3i6ar7tzqksxubq28g0kzsej9"} D, [2017-08-15T14:13:52.839492 #2340] DEBUG -- : [oauth2] Success! D, [2017-08-15T14:13:52.839616 #2340] DEBUG -- : [oauth2] Session=#<SparkApi::Authentication::OAuthSession:0x0000000376b210 @access_token="a9741naj3hbe64e8832aco48e", @expires_in=86400, @scope=nil, @refresh_token="3i6ar7tzqksxubq28g0kzsej9", @start_time=#<DateTime: 2017-08-15T14:13:52-05:00 ((2457981j,69232s,839552375n),-18000s,2299161j)>, @refresh_timeout=43200> D, [2017-08-15T14:13:52.839667 #2340] DEBUG -- : [oauth2] New session created # I, [2017-08-15T14:13:52.839701 #2340] INFO -- : [0ms] D, [2017-08-15T14:13:52.839737 #2340] DEBUG -- : Session: #<SparkApi::Authentication::OAuthSession:0x0000000376b210 @access_token="a9741naj3hbe64e8832aco48e", @expires_in=86400, @scope=nil, @refresh_token="3i6ar7tzqksxubq28g0kzsej9", @start_time=#<DateTime: 2017-08-15T14:13:52-05:00 ((2457981j,69232s,839552375n),-18000s,2299161j)>, @refresh_timeout=43200> D, [2017-08-15T14:13:52.840194 #2340] DEBUG -- : Connection: #<Faraday::Connection:0x000000037693e8 @parallel_manager=nil, @headers={"Accept"=>"application/json", "Content-Type"=>"application/json", "User-Agent"=>"Spark API Ruby Gem 1.4.15", "X-SparkApi-User-Agent"=>"Spark API Ruby Gem 1.4.15"}, @params={}, @options=#, @ssl=#<Faraday::SSLOptions (empty)>, @default_parallel_manager=nil, @builder=#<Faraday::RackBuilder:0x00000003768fb0 @handlers=[SparkApi::FaradayMiddleware, Faraday::Adapter::NetHttp]>, @url_prefix=#<URI::HTTPS:0x00000003768d30 URL:https://sparkapi.com/>, @proxy=nil> D, [2017-08-15T14:13:52.840248 #2340] DEBUG -- : Request: /v1/system D, [2017-08-15T14:13:52.948453 #2340] DEBUG -- : Response Body: {"D"=>{"Results"=>[{"Name"=>"Leonardo Da Vinci", "Id"=>"20130628181124193288000000", "Office"=>"FBS Test Office"...} D, [2017-08-15T14:13:52.948562 #2340] DEBUG -- : Success! D, [2017-08-15T14:13:52.948608 #2340] DEBUG -- : [108ms] Api: GET /v1/system System metadata: [{"Name"=>"Leonardo Da Vinci", "Id"=>"20130628181124193288000000"...}]

I'm still looking into your latter question of if a refresh works on recently expired tokens.

[ridley-james]

@danwoolley after further checking, refreshing does work on expired tokens.

[danwoolley]

I've verified that all of the above is true on my side. Thanks guys. I think you can close this ticket.

My plan is to query all my sessions every 12 hours to see which ones are within the window between the refresh_timeout and the expires_in and do a client.authenticate on each, saving the new session. I believe this should ensure that sessions stay authenticated for a very long time. Does that sound right?

[ridley-james]

I'm not sure it is necessary as sessions should auto refresh after expiration, but it would not hurt to have a process refresh sessions proactively.