Token invalidation does not occur in test environments

[TomasBarry]

Describe the bug

When using the same token in two requests in a spec file the second request accepts the then expired token.

Environment

devise (4.7.3)
  bcrypt (~> 3.0)
  orm_adapter (~> 0.1)
  railties (>= 4.1.0)
  responders
  warden (~> 1.2.3)
devise_token_auth (1.1.5)
  bcrypt (~> 3.0)
  devise (> 3.5.2, < 5)
  rails (>= 4.2.0, < 6.2)

graphiql-rails (1.7.0)
  railties
  sprockets-rails
graphql (1.12.12)
graphql_devise (0.17.0)
  devise_token_auth (>= 0.1.43, < 2.0)
  graphql (>= 1.8, < 1.13.0)
  rails (>= 4.2, < 6.2)

Steps to reproduce

user = create(:user)

query_string = <<-GRAPHQL
  query {
    user(id: "#{user.id}") {
      firstName
    }
  }
GRAPHQL

auth_headers = user.create_new_auth_token
request.headers.merge!(auth_headers)

post(
  :execute,
  params: {
    query: query_string
  }
)

expect(response).to have_http_status(:ok)
parsed_body = JSON.parse(response.body)
# This is something like {"data"=>{"user"=>{"firstName"=>"Lowell"}}}

# ensure that we're not sending the request in the allowed batch time
sleep(DeviseTokenAuth.batch_request_buffer_throttle + 1.second)

request.headers.merge!(auth_headers) # The old access-token
post(
  :execute,
  params: {
    query: query_string
  }
)

expect(response).to have_http_status(:ok)
parsed_body = JSON.parse(response.body)
# This is still like {"data"=>{"user"=>{"firstName"=>"Lowell"}}}

# I would expect the following expectations to be valid
expect(parsed_body['data']).to be_nil
expect(parsed_body['errors'].count).to eq(1)
expect(parsed_body['errors'].first['message'])
  .to eq('user field requires authentication')

Using Timecop results in the same issue.

Expected behavior

I would expect the second request to return an error.

Actual behavior

The second request returns the requested data.

[mcelicalderon]

Hey @TomasBarry! Did you set change_headers_on_each_request to true in the dta initializer?

[TomasBarry]

@mcelicalderon, yes. What I find strange too is that before the second request, the response headers look like:

response.headers
# { "access-token"=>" ", "token-type"=>"Bearer", "client"=>"SOME_ID", "expiry"=>" ", "uid"=>"SOME_EMAIL" }

See how the access-token value is just a blank space (as is the expiry)?

However, after the second request the access-token and expiry do have values that are different to the auth_headers but a third request with the old headers (in auth_headers) still succeeds (even after the batch_request_buffer_throttle time).

[mcelicalderon]

Hey @TomasBarry, thank you for looking into this. I think I might know where the problem is, but until I get to look into it, could you please share how your graphql_controller is setup? Knowing how you are authenticating the user would be very helpful as there are currently a couple of ways to do it, some of them already deprecated. Also, if you are mounting the gem on your schema via the plugin only or if you might also be using the mount method in your routes file. Thanks!

[TomasBarry]

Sure thing @mcelicalderon.

Here is our x_schema.rb file:

class XSchema < GraphQL::Schema
  # github.com/graphql-devise/graphql_devise#mounting-operations-into-your-own-schema
  use(GraphqlDevise::SchemaPlugin.new(
    query: Types::QueryType,
    mutation: Types::MutationType,
    resource_loaders: [
      GraphqlDevise::ResourceLoader.new(User, {
        skip: [
          :sign_up,
          :update_password,
          :send_password_reset,
          :resend_confirmation,
          :confirm_account,
          :check_password_token,
          :confirm_registration_with_token
        ],
        authenticatable_type: Types::Model::UserType
      })
    ],
    authenticate_default: true,
    public_introspection: true
  ))

  mutation(Types::MutationType)
  query(Types::QueryType)

  use(BatchLoader::GraphQL)
  use(GraphQL::Tracing::ScoutTracing, set_transaction_name: true)
end

Here is our controller:

class GraphqlController < ApplicationController
  include GraphqlDevise::Concerns::SetUserByToken

  # If accessing from outside this domain, nullify the session
  # This allows for outside API access while preventing CSRF attacks,
  # but you'll have to authenticate your user separately
  protect_from_forgery with: :null_session

  def execute
    result = ButternutBoxSchema.execute(
      query,
      variables: variables,
      context: context,
      operation_name: operation_name
    )
    render(json: result) unless performed?
  rescue => e
    raise e unless Rails.env.development?

    handle_error_in_development(e)
  end

  private

  def variables
    ensure_hash(params[:variables])
  end

  def query
    params[:query]
  end

  def operation_name
    params[:operationName]
  end

  def context
    {
      **gql_devise_context(User)
    }
  end

  # Handle form data, JSON body, or a blank value
  def ensure_hash(ambiguous_param) # rubocop:disable Metrics/MethodLength
    case ambiguous_param
    when String
      if ambiguous_param.present?
        ensure_hash(JSON.parse(ambiguous_param))
      else
        {}
      end
    when Hash, ActionController::Parameters
      ambiguous_param
    when nil
      {}
    else
      raise ArgumentError, "Unexpected parameter: #{ambiguous_param}"
    end
  end

  def handle_error_in_development(error)
    logger.error(error.message)
    logger.error(error.backtrace.join("\n"))

    error = { message: error.message, backtrace: error.backtrace }
    render(
      json: {
        error: error,
        data: {}
      },
      status: :internal_server_error
    )
  end
end

We are mounting the plugin through the schema only.

My understanding was that using gql_devise_context to authenticate the user was the suggested and non-deprecated approach and then in context[:current_resource] you have the authenticated resource, in this case, our user. That is correct, right?

To clarify, this problem only appears to be present in the test environment though.

Is there anything problematic with what you see above?

[mcelicalderon]

@TomasBarry thank you for providing details on your implementation. I still haven't been able to take a closer look at this, but I'm pretty sure of what I might be (specially if you are not seeing this problem in production). A workaround for problems like this was discussed in https://github.com/graphql-devise/graphql_devise/issues/151#issuecomment-780080312

please take a look and that will probably work while I work on the real fix. It's probably related to the fact that the schema plugin won't mount the resource in Devise before the first request is made. We fixed that for authentication but I guess I overlooked token regeneration.

[TomasBarry]

@mcelicalderon, so it's just an issue in a test environment?

[mcelicalderon]

That's my guess as I haven't been able to take a closer look yet. So, you could try enabling eager load in your test environment and see if that fixes the problem for now.

[TomasBarry]

@mcelicalderon:

Changed to eager loading in test and the issue is still there. Even though when I look at the users token they are being updated it seems that old tokens are still considered valid. A bit unsure as to why this would be the case. Here's a bit of a log of what's happening:

user = create(:user)

user.tokens
# {}

auth_headers = user.create_new_auth_token
# {"CLIENT_ID_1"=>{"token"=>"TOKEN_1", "expiry"=>1626786670, "updated_at"=>"2021-07-06T13:11:10Z"}}

post(:execute, params: { query: query_string })

response.headers
# {"access-token"=>"SOME_TOKEN", "token-type"=>"Bearer", "client"=>"CLIENT_ID_1", "expiry"=>"1626786748", "uid"=>"EMAIL"}

user.reload
user.tokens

# {"CLIENT_ID_1"=>{"token"=>"TOKEN_2", "expiry"=>1626786748, "last_token"=>"TOKEN_1", "updated_at"=>"2021-07-06T13:12:28Z"}}

So the user.tokens is being updated. But making a request with an old access token is still authenticated when it shouldn't be. Notably, if I Timecop until after expiry, the token is considered invalid. This seems to just be a problem with rejecting tokens that have already been used (and I do have config.change_headers_on_each_request = true already set)

[mcelicalderon]

So, after enabling eager load is the problem with the first request gone? I mean an empty token on the response.

For the other token remaining valid, how soon after the first request are you making the next one? There's a configuration in devise token auth that will allow the token to remain valid for a certain amount of time so you are able to batch requests. I think the default might be 5 seconds before it becomes invalid. https://github.com/graphql-devise/graphql_devise/blob/a69b27a402933861304ebb35707b130092d15b4f/spec/dummy/config/initializers/devise_token_auth.rb#L27

[TomasBarry]

@mcelicalderon, regarding batch_request_buffer_throttle. I'm waiting until after this throttle time. I've tried both sleeping for batch_request_buffer_throttle + 1.second and Timecopping to after that buffer time. That's what's confusing me, in production this behaves as expected but in test I can't seem to get the error on token re-use (after the throttle time).

[TomasBarry]

@mcelicalderon any further ideas on this one?

[mcelicalderon]

Hey @TomasBarry, sorry we haven't been able to look into this yet. I'll try to look into this over the weekend. No more ideas of the top of my head. I can't think of another reason why it could behave differently in dev/test other than the eager load setting.

[mcelicalderon]

If you could provide a small sample project where the errors is replicated that would be ideal so I can test the same conditions you are

[00dav00]

Hi @TomasBarry, validating wether or not a token is valid is handled by DTA at the moment, I think you may find the answer to this unexpected behavior checking valid_token?, token_is_current? and token_can_be_reused?.

Another change that I think can help your tests is saving the user instance (.save) inside of the timecop/travel block so that destroy_expired_tokens is triggered.

Please let us know what happen when you tap into into this methods.

[TomasBarry]

@00dav00, valid_token? actually returns true which seems to be the issue.

Going line by line, user.token_is_current? returns true even though it's already been used.

[mcelicalderon]

Hey @TomasBarry, I was finally able to look into this and found the issue. It looks like DTA uses updated_at on the created token to identify if a request is a batch request. Related code here. For this reason, if you create a new token and don't wait at least as many seconds as the throttle value before making the first request, DTA will consider the first request a batch request and then not behave as expected.

I don't think this is something we should fix in this gem, but I'll keep looking a bit more into it. What you can do now as a workaround is making sure you wait at least as much as the configured throttle time between creating a new token and making the first request. Then of course you will also have to sleep or use time_travel to wait enough for the second request. This piece of code illustrates how to make it fail if throttle is configured for 1.second:

context 'when authenticating before using the GQL schema' do
  before do
    headers
    sleep 5
    post_request('/api/v1/controller_auth')
  end

  context 'when user is authenticated' do
    let(:e_user) { create(:schema_user) }
    let(:headers) { e_user.create_new_auth_token }

     it 'allows authentication at the controller level' do
       sleep 5
       # This request will fail
       post_request('/api/v1/controller_auth')
     end
   end
end

Update: Let me know if that worked and I think we can close this issue. Not sure if there's a better way to do what DTA is currently doing, but in any case, that's something that should be fixed over there. Now that I think about it, it should probably be fixed as for whatever reason, you could use your login token immediately after getting it in a production app and then getting this erroneous behavior.

[TomasBarry]

@mcelicalderon, that makes sense. However, I can't replicate your failure:

auth_headers = user.create_new_auth_token
sleep(DeviseTokenAuth.batch_request_buffer_throttle + 1.second)

request.headers.merge!(auth_headers)
post(:execute, params: { query: query_string })

sleep(DeviseTokenAuth.batch_request_buffer_throttle + 1.second)
post(:execute, params: { query: query_string })

The same headers are used in both queries but the second query still succeeds. The same is true with Timecop. Do you have an example repo/branch where I can see your example working and I'll debug from there?

[mcelicalderon]

Sure, @TomasBarry here's a branch where I changed a single spec. Others will fail as we were not testing with tokens valid for a single request setting enabled. But take a look at the commit and you'll see the expectation works. Also, here's my Gemfile.lock so you can check if it's related to a version of a dependency.

branch commit (for future reference)

Gemfile.lock

```ruby PATH remote: . specs: graphql_devise (0.17.1) devise_token_auth (>= 0.1.43, < 2.0) graphql (>= 1.8, < 1.13.0) rails (>= 4.2, < 6.2) GEM remote: https://rubygems.org/ specs: actioncable (6.1.3.2) actionpack (= 6.1.3.2) activesupport (= 6.1.3.2) nio4r (~> 2.0) websocket-driver (>= 0.6.1) actionmailbox (6.1.3.2) actionpack (= 6.1.3.2) activejob (= 6.1.3.2) activerecord (= 6.1.3.2) activestorage (= 6.1.3.2) activesupport (= 6.1.3.2) mail (>= 2.7.1) actionmailer (6.1.3.2) actionpack (= 6.1.3.2) actionview (= 6.1.3.2) activejob (= 6.1.3.2) activesupport (= 6.1.3.2) mail (~> 2.5, >= 2.5.4) rails-dom-testing (~> 2.0) actionpack (6.1.3.2) actionview (= 6.1.3.2) activesupport (= 6.1.3.2) rack (~> 2.0, >= 2.0.9) rack-test (>= 0.6.3) rails-dom-testing (~> 2.0) rails-html-sanitizer (~> 1.0, >= 1.2.0) actiontext (6.1.3.2) actionpack (= 6.1.3.2) activerecord (= 6.1.3.2) activestorage (= 6.1.3.2) activesupport (= 6.1.3.2) nokogiri (>= 1.8.5) actionview (6.1.3.2) activesupport (= 6.1.3.2) builder (~> 3.1) erubi (~> 1.4) rails-dom-testing (~> 2.0) rails-html-sanitizer (~> 1.1, >= 1.2.0) activejob (6.1.3.2) activesupport (= 6.1.3.2) globalid (>= 0.3.6) activemodel (6.1.3.2) activesupport (= 6.1.3.2) activerecord (6.1.3.2) activemodel (= 6.1.3.2) activesupport (= 6.1.3.2) activestorage (6.1.3.2) actionpack (= 6.1.3.2) activejob (= 6.1.3.2) activerecord (= 6.1.3.2) activesupport (= 6.1.3.2) marcel (~> 1.0.0) mini_mime (~> 1.0.2) activesupport (6.1.3.2) concurrent-ruby (~> 1.0, >= 1.0.2) i18n (>= 1.6, < 2) minitest (>= 5.1) tzinfo (~> 2.0) zeitwerk (~> 2.3) addressable (2.7.0) public_suffix (>= 2.0.2, < 5.0) appraisal (2.4.0) bundler rake thor (>= 0.14.0) ast (2.4.2) async (1.29.0) console (~> 1.10) nio4r (~> 2.3) timers (~> 4.1) async-http (0.56.3) async (~> 1.25) async-io (~> 1.28) async-pool (~> 0.2) protocol-http (~> 0.22.0) protocol-http1 (~> 0.14.0) protocol-http2 (~> 0.14.0) async-http-faraday (0.9.0) async-http (~> 0.42) faraday async-io (1.32.1) async (~> 1.14) async-pool (0.3.7) async (~> 1.25) bcrypt (3.1.16) builder (3.2.4) byebug (11.1.3) coderay (1.1.3) concurrent-ruby (1.1.9) console (1.12.0) fiber-local coveralls-ruby (0.2.0) json (>= 1.8, < 3) simplecov (~> 0.16.1) term-ansicolor (~> 1.3) thor (>= 0.19.4, < 2.0) tins (~> 1.6) crass (1.0.6) devise (4.8.0) bcrypt (~> 3.0) orm_adapter (~> 0.1) railties (>= 4.1.0) responders warden (~> 1.2.3) devise_token_auth (1.2.0) bcrypt (~> 3.0) devise (> 3.5.2, < 5) rails (>= 4.2.0, < 6.2) diff-lcs (1.4.4) docile (1.3.5) erubi (1.10.0) factory_bot (6.2.0) activesupport (>= 5.0.0) faker (2.17.0) i18n (>= 1.6, < 2) faraday (1.4.2) faraday-em_http (~> 1.0) faraday-em_synchrony (~> 1.0) faraday-excon (~> 1.1) faraday-net_http (~> 1.0) faraday-net_http_persistent (~> 1.1) multipart-post (>= 1.2, < 3) ruby2_keywords (>= 0.0.4) faraday-em_http (1.0.0) faraday-em_synchrony (1.0.0) faraday-excon (1.1.0) faraday-http-cache (2.2.0) faraday (>= 0.8) faraday-net_http (1.0.1) faraday-net_http_persistent (1.1.0) fiber-local (1.0.0) generator_spec (0.9.4) activesupport (>= 3.0.0) railties (>= 3.0.0) github_changelog_generator (1.16.4) activesupport async (>= 1.25.0) async-http-faraday faraday-http-cache multi_json octokit (~> 4.6) rainbow (>= 2.2.1) rake (>= 10.0) globalid (0.5.2) activesupport (>= 5.0) graphql (1.12.14) i18n (1.8.10) concurrent-ruby (~> 1.0) jaro_winkler (1.5.4) json (2.5.1) loofah (2.9.1) crass (~> 1.0.2) nokogiri (>= 1.5.9) mail (2.7.1) mini_mime (>= 0.1.1) marcel (1.0.1) method_source (0.9.2) mini_mime (1.0.3) mini_portile2 (2.5.3) minitest (5.14.4) multi_json (1.15.0) multipart-post (2.1.1) nio4r (2.5.7) nokogiri (1.11.3) mini_portile2 (~> 2.5.0) racc (~> 1.4) nokogiri (1.11.3-x86_64-darwin) racc (~> 1.4) octokit (4.21.0) faraday (>= 0.9) sawyer (~> 0.8.0, >= 0.5.3) orm_adapter (0.5.0) parallel (1.20.1) parser (3.0.1.1) ast (~> 2.4.1) protocol-hpack (1.4.2) protocol-http (0.22.2) protocol-http1 (0.14.1) protocol-http (~> 0.22) protocol-http2 (0.14.2) protocol-hpack (~> 1.4) protocol-http (~> 0.18) pry (0.12.2) coderay (~> 1.1.0) method_source (~> 0.9.0) pry-byebug (3.8.0) byebug (~> 11.0) pry (~> 0.10) public_suffix (4.0.6) racc (1.5.2) rack (2.2.3) rack-test (1.1.0) rack (>= 1.0, < 3) rails (6.1.3.2) actioncable (= 6.1.3.2) actionmailbox (= 6.1.3.2) actionmailer (= 6.1.3.2) actionpack (= 6.1.3.2) actiontext (= 6.1.3.2) actionview (= 6.1.3.2) activejob (= 6.1.3.2) activemodel (= 6.1.3.2) activerecord (= 6.1.3.2) activestorage (= 6.1.3.2) activesupport (= 6.1.3.2) bundler (>= 1.15.0) railties (= 6.1.3.2) sprockets-rails (>= 2.0.0) rails-dom-testing (2.0.3) activesupport (>= 4.2.0) nokogiri (>= 1.6) rails-html-sanitizer (1.3.0) loofah (~> 2.3) railties (6.1.3.2) actionpack (= 6.1.3.2) activesupport (= 6.1.3.2) method_source rake (>= 0.8.7) thor (~> 1.0) rainbow (3.0.0) rake (13.0.3) responders (3.0.1) actionpack (>= 5.0) railties (>= 5.0) rspec-core (3.10.1) rspec-support (~> 3.10.0) rspec-expectations (3.10.1) diff-lcs (>= 1.2.0, < 2.0) rspec-support (~> 3.10.0) rspec-mocks (3.10.2) diff-lcs (>= 1.2.0, < 2.0) rspec-support (~> 3.10.0) rspec-rails (4.1.2) actionpack (>= 4.2) activesupport (>= 4.2) railties (>= 4.2) rspec-core (~> 3.10) rspec-expectations (~> 3.10) rspec-mocks (~> 3.10) rspec-support (~> 3.10) rspec-support (3.10.2) rubocop (0.68.1) jaro_winkler (~> 1.5.1) parallel (~> 1.10) parser (>= 2.5, != 2.5.1.1) rainbow (>= 2.2.2, < 4.0) ruby-progressbar (~> 1.7) unicode-display_width (>= 1.4.0, < 1.6) rubocop-performance (1.3.0) rubocop (>= 0.68.0) rubocop-rspec (1.41.0) rubocop (>= 0.68.1) ruby-progressbar (1.11.0) ruby2_keywords (0.0.4) sawyer (0.8.2) addressable (>= 2.3.5) faraday (> 0.8, < 2.0) simplecov (0.16.1) docile (~> 1.1) json (>= 1.8, < 3) simplecov-html (~> 0.10.0) simplecov-html (0.10.2) sprockets (4.0.2) concurrent-ruby (~> 1.0) rack (> 1, < 3) sprockets-rails (3.2.2) actionpack (>= 4.0) activesupport (>= 4.0) sprockets (>= 3.0.0) sqlite3 (1.4.2) sync (0.5.0) term-ansicolor (1.7.1) tins (~> 1.0) thor (1.1.0) timers (4.3.3) tins (1.29.0) sync tzinfo (2.0.4) concurrent-ruby (~> 1.0) unicode-display_width (1.5.0) warden (1.2.9) rack (>= 2.0.9) websocket-driver (0.7.5) websocket-extensions (>= 0.1.0) websocket-extensions (0.1.5) zeitwerk (2.4.2) PLATFORMS ruby x86_64-darwin-19 DEPENDENCIES appraisal coveralls-ruby (~> 0.2) factory_bot faker generator_spec github_changelog_generator graphql_devise! pry (~> 0.12.2) pry-byebug rake (>= 12.3.3) rspec-rails (~> 4.0) rubocop (= 0.68.1) rubocop-performance rubocop-rspec sqlite3 (~> 1.3) BUNDLED WITH 1.17.3 ```

[mcelicalderon]

Yes, @TomasBarry that one is definitively passing (I mean the first request, you can inspect that). I changed an existing spec to test this, didn't give it much thought as we are not keeping the spec like that. I would advise using a gem like pry to debug further. Our helper method post_request will use whatever you have defined as headers on every request you make via post_request

[TomasBarry]

@mcelicalderon, nice. Playing with that commit it looks fine. Will keep digging in on my side I imagine it's something on the setup we're doing.

Thanks for digging into this.

[mcelicalderon]

No problem, @TomasBarry. I'm closing this one as that appears to be the problem and the issue should be moved to DTA. Feel free to reopen if you run into something else. I might open an issue on DTA if you don't.