Intermittent invalid_credentials error

[marckohlbrugge]

I get an intermittent invalid_credentials. It's not specific to any user accounts. After attempting to login about 10 times, I get this error message. It originates in the failure controller action.

I've added some logging like this:

  def failure
    Rails.logger.error "OmniAuth hash: #{request.env['omniauth.auth'].inspect}"
    Rails.logger.error "OmniAuth authentication failure: #{params[:message]}"
    Rails.logger.error "OmniAuth strategy: #{params[:strategy]}"
    Rails.logger.error "OmniAuth error: #{params[:error]}"
    Rails.logger.error "OmniAuth error reason: #{params[:error_reason]}"
    Rails.logger.error "OmniAuth error description: #{params[:error_description]}"

    redirect_to sign_in_path, alert: params[:message]
  end

And here's my logs:

2024-12-10T23:25:33.101949912Z D, [2024-12-10T23:25:33.101798 #60] DEBUG -- omniauth: (twitter) Callback phase initiated.
2024-12-10T23:25:33.217303345Z E, [2024-12-10T23:25:33.216871 #60] ERROR -- omniauth: (twitter) Authentication failure! invalid_credentials: OAuth::Unauthorized, 401 Unauthorized
2024-12-10T23:25:33.218402278Z {"time":"2024-12-10T23:25:33.21829577Z","level":"INFO","msg":"Request","path":"/auth/twitter/callback","status":302,"dur":118,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":9,"resp_content_type":"text/plain; charset=utf-8","remote_addr":"2a02:REMOVEDFORGITHUB, 172.REMOVEDFORGITHUB","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.1.1 Safari/605.1.15","cache":"miss","query":"oauth_token=z6GYlQAAAAREMOVEDFORGITHUB&oauth_verifier=sPkdVK43GJnREMOVEDFORGITHUB"}
2024-12-10T23:25:33.402981747Z I, [2024-12-10T23:25:33.402717 #60]  INFO -- : [f15d3743-bf29-4859-a00e-d2e637604039] Started GET "/auth/failure?message=invalid_credentials&strategy=twitter" for 2a02:26f7:cb02:5293:0:7d:21f:875f at 2024-12-10 23:25:33 +0000
2024-12-10T23:25:33.405106026Z I, [2024-12-10T23:25:33.404950 #60]  INFO -- : [f15d3743-bf29-4859-a00e-d2e637604039] Processing by Sessions::OmniauthController#failure as HTML
2024-12-10T23:25:33.405158066Z I, [2024-12-10T23:25:33.405016 #60]  INFO -- : [f15d3743-bf29-4859-a00e-d2e637604039]   Parameters: {"message"=>"invalid_credentials", "strategy"=>"twitter"}
2024-12-10T23:25:33.408427129Z E, [2024-12-10T23:25:33.408294 #60] ERROR -- : [f15d3743-bf29-4859-a00e-d2e637604039] OmniAuth hash: nil
2024-12-10T23:25:33.408728114Z E, [2024-12-10T23:25:33.408472 #60] ERROR -- : [f15d3743-bf29-4859-a00e-d2e637604039] OmniAuth authentication failure: invalid_credentials
2024-12-10T23:25:33.408738584Z E, [2024-12-10T23:25:33.408515 #60] ERROR -- : [f15d3743-bf29-4859-a00e-d2e637604039] OmniAuth strategy: twitter
2024-12-10T23:25:33.408741774Z E, [2024-12-10T23:25:33.408532 #60] ERROR -- : [f15d3743-bf29-4859-a00e-d2e637604039] OmniAuth error: 
2024-12-10T23:25:33.408744714Z E, [2024-12-10T23:25:33.408552 #60] ERROR -- : [f15d3743-bf29-4859-a00e-d2e637604039] OmniAuth error reason: 
2024-12-10T23:25:33.408747084Z E, [2024-12-10T23:25:33.408568 #60] ERROR -- : [f15d3743-bf29-4859-a00e-d2e637604039] OmniAuth error description: 
2024-12-10T23:25:33.410035845Z I, [2024-12-10T23:25:33.409942 #60]  INFO -- : [f15d3743-bf29-4859-a00e-d2e637604039] Redirected to https://REMOVEDFORGITHUB/sign_in
2024-12-10T23:25:33.410162973Z I, [2024-12-10T23:25:33.410082 #60]  INFO -- : [f15d3743-bf29-4859-a00e-d2e637604039] Completed 302 Found in 5ms (ActiveRecord: 0.7ms (1 query, 0 cached) | GC: 0.0ms)
2024-12-10T23:25:33.411337936Z {"time":"2024-12-10T23:25:33.411027531Z","level":"INFO","msg":"Request","path":"/auth/failure","status":302,"dur":9,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":0,"resp_content_type":"text/html; charset=utf-8","remote_addr":"2a02:REMOVEDFORGITHUB, 172.REMOVEDFORGITHUB","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.1.1 Safari/605.1.15","cache":"miss","query":"message=invalid_credentials&strategy=twitter"}

The fact it can happen for the same user, and the fact that 90% of the times everything works fine (using the exact same login flow), suggests to me this is NOT a configuration error like many other "401 Unauthorized" problems tend to be.

Any idea what might be causing this erratic behavior? Ideas on how to better debug it?