oauth2-proxy: CookieRefresh option does not refresh session age, spams logs

When a session is old enough to be “refreshed”, its age is never reset, causing subsequent authenticated requests to continually spam “Refreshing old session cookie” in the logs.

Expected Behavior

When:

--cookie-refresh=1m is set
multiple calls to /oauth2/auth are made over the course of several minutes

I expect that:

in the logs, at most 1 request per minute has a “Refreshing old session cookie” message
in the logs, the age of this request message never significantly exceeds my --cookie-refresh parameter.
On the client, I see an updated cookie with a new CreatedAt

Current Behavior

For simple CookieSession sessions backed by basic auth, every request after the initial refresh duration logs a “Refresh” message.

For OIDC sessions backed by redis, it appears to continually re-authenticate an unexpired access token, until eventually the access token expires.

Possible Solution

When a session should be refreshed, it’s CreatedAt could be reset to now. Alternatively, a second RefreshedAt could be tracked. Alternatively, the --cookie-refresh option could be removed.

Steps to Reproduce (for bugs)

A simple reproduction of the case:

Run a test oauth2_proxy (using password file auth for test simplicity)

docker run --mount type=bind,source=/path/to/passwordfolder,target=/data -p 127.0.0.1:4180:4180 quay.io/oauth2-proxy/oauth2-proxy  -http-address='0.0.0.0:4180' -htpasswd-file=/data/passwords.txt -cookie-secret='YmJiYmJiYmJiYmJiYmJiYg==' -client-id=foo -client-secret=bar -cookie-secure=false -cookie-refresh=60s

curl -c cookies.txt -v 'http://127.0.0.1:4180/oauth2/sign_in' --data 'rd=%2F&username=testuser&password=testpassword'

continually re-request authentication status

while true; do
  date
  curl -v '127.0.0.1:4180/oauth2/auth' -c cookies.txt -b cookies.txt
  md5 cookies.txt
  tail -n1 cookies.txt | ruby -rbase64 -rjson -ne 'p JSON.parse(Base64.decode64($_.split.last.split("|").first))'
  sleep 15
done

observe the log output: oauth2_proxy:

172.17.0.1 - testuser [2020/04/13 23:33:58] [AuthSuccess] Authenticated via HtpasswdFile
172.17.0.1 - - [2020/04/13 23:33:58] 127.0.0.1:4180 POST - "/oauth2/sign_in" HTTP/1.1 "curl/7.54.0" 302 0 0.000
172.17.0.1 - testuser [2020/04/13 23:34:03] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.000
172.17.0.1 - testuser [2020/04/13 23:34:18] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.000
172.17.0.1 - testuser [2020/04/13 23:34:33] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.000
172.17.0.1 - testuser [2020/04/13 23:34:49] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.001
[2020/04/13 23:35:04] [oauthproxy.go:872] Refreshing 1m5.5872417s old session cookie for Session{email: user:testuser PreferredUsername: created:2020-04-13 23:33:58.4127583 +0000 UTC} (refresh after 1m0s)
172.17.0.1 - testuser [2020/04/13 23:35:04] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.001
[2020/04/13 23:35:19] [oauthproxy.go:872] Refreshing 1m20.5872417s old session cookie for Session{email: user:testuser PreferredUsername: created:2020-04-13 23:33:58.4127583 +0000 UTC} (refresh after 1m0s)
172.17.0.1 - testuser [2020/04/13 23:35:19] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.000
[2020/04/13 23:35:35] [oauthproxy.go:872] Refreshing 1m36.5872417s old session cookie for Session{email: user:testuser PreferredUsername: created:2020-04-13 23:33:58.4127583 +0000 UTC} (refresh after 1m0s)
172.17.0.1 - testuser [2020/04/13 23:35:35] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.000
[2020/04/13 23:35:50] [oauthproxy.go:872] Refreshing 1m51.5872417s old session cookie for Session{email: user:testuser PreferredUsername: created:2020-04-13 23:33:58.4127583 +0000 UTC} (refresh after 1m0s)
172.17.0.1 - testuser [2020/04/13 23:35:50] 127.0.0.1:4180 GET - "/oauth2/auth" HTTP/1.1 "curl/7.54.0" 202 0 0.001

bash(edited)

MD5 (cookies.txt) = 19502faba8fd0ea08293130b8b577904
{"User"=>"7F31PtJ13MC1MRepdbxdR57tHIRDAHq7", "CreatedAt"=>"2020-04-13T23:33:58.4127583Z"}
...
MD5 (cookies.txt) = 7e53bd520ddb9dc1e9d7e9830fc7557c
{"User"=>"0WsAYW4zvAIKq9kvkba7hPjLg7Lsqbuh", "CreatedAt"=>"2020-04-13T23:33:58.4127583Z"}
...
MD5 (cookies.txt) = 0eb4c50b0a28563df35574bc5674a11a
{"User"=>"oP6+kfZDu6MitpHE007d0Pz+7265EWEh", "CreatedAt"=>"2020-04-13T23:33:58.4127583Z"}
...

Context

While investigating other issues related to traffic and redirect loops, I was led astray by the surprising frequency of these Refresh messages, especially frequent & continual Refreshes for the same user that were well after the --cookie-refresh parameter.

Your Environment

We’re using oauth2-proxy as a delegated authentication endpoint for ingress-nginx in kubernetes. However, the same issue reproduces outside that environment.

About this issue

Original URL
State: closed
Created 4 years ago
Reactions: 1
Comments: 56 (30 by maintainers)

Most upvoted comments

Thank you for the feedback - I managed to trace it down to missing scope offline_access - with that scope the refresh token will be properly issued from okta.

patrickjahns on Jun 5, 2023

@JoelSpeed I’ve had the same experience as @idntfy.

I have a pretty simple setup: oauth2_proxy, nginx, and an upstream service. I used to run oauth2_proxy v2.2 (or possibly earlier, I forget) in a non-containerized environment with Google as the auth provider. Token refresh worked great.

I updated my setup summer of last year to docker, which included bringing oauth2_proxy up to date. Google is still being used as the auth provider. Token refresh has been broken ever since. This issue is easily reproducible by setting the cookie refresh and expire parameter to low values.

From a user POV, this is a regression. I very much care about token refreshing, as it kinda sucks asking my users to log in so frequently, whereas before it just worked.

Am I understanding correctly that #1063 may fix the issue, but we have to add redis to our setup to take advantage of the fix? Is there any way to not require redis? I really don’t want to add any more complexity to my setup. Edit: Is it #1086 that would fix this?

Logs below were from reloading the page, with oauth2_proxy v7.1.3, cookie-refresh=25s, and cookie-expire=60s:

[2021/06/22 19:45:00] [stored_session.go:122] Refreshing 48.675563336s old session cookie for Session{email:sanitized@sanitized.com user:<sanitized_user_id> PreferredUsername: token:true id_token:true created:2021-06-22 19:44:11.324436664 +0000 UTC expires:2021-06-22 20:44:10 +0000 UTC refresh_token:true} (refresh after 25s)
[2021/06/22 19:45:00] [stored_session.go:122] Refreshing 48.675563336s old session cookie for Session{email:sanitized@sanitized.com user:<sanitized_user_id> PreferredUsername: token:true id_token:true created:2021-06-22 19:44:11.324436664 +0000 UTC expires:2021-06-22 20:44:10 +0000 UTC refresh_token:true} (refresh after 25s)
[2021/06/22 19:45:00] [internal_util.go:69] 200 GET https://www.googleapis.com/oauth2/v1/tokeninfo?access_token=<sanitized_token>... {
  "issued_to": "sanitized.apps.googleusercontent.com",
  "audience": "sanitized.apps.googleusercontent.com",
  "user_id": "<sanitized_user_id>",
  "scope": "https://www.googleapis.com/auth/userinfo.profile https://www.googleapis.com/auth/userinfo.email openid",
  "expires_in": 3550,
  "email": "sanitized@sanitized.com",
  "verified_email": true,
  "access_type": "offline"
}

<sanitized_ip> - ebcf10ee-8b75-430d-8689-b0ac6b9a0231 - sanitized@sanitized.com [2021/06/22 19:45:00] sanitized.com GET - "/oauth2/auth" HTTP/1.0 "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36 Edg/91.0.864.54" 202 0 0.048
[2021/06/22 19:45:00] [internal_util.go:69] 200 GET https://www.googleapis.com/oauth2/v1/tokeninfo?access_token=<sanitized_token>... {
  "issued_to": "sanitized.apps.googleusercontent.com",
  "audience": "sanitized.apps.googleusercontent.com",
  "user_id": "<sanitized_user_id>",
  "scope": "https://www.googleapis.com/auth/userinfo.profile https://www.googleapis.com/auth/userinfo.email openid",
  "expires_in": 3550,
  "email": "sanitized@sanitized.com",
  "verified_email": true,
  "access_type": "offline"
}


<sanitized_ip> - 6b89d687-af12-455e-8a71-242994a2f5fe - sanitized@sanitized.com [2021/06/22 19:45:00] sanitized.com GET - "/oauth2/auth" HTTP/1.0 "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36 Edg/91.0.864.54" 202 0 0.043
[2021/06/22 19:45:00] [stored_session.go:122] Refreshing 48.675563336s old session cookie for Session{email:sanitized@sanitized.com user:<sanitized_user_id> PreferredUsername: token:true id_token:true created:2021-06-22 19:44:11.324436664 +0000 UTC expires:2021-06-22 20:44:10 +0000 UTC refresh_token:true} (refresh after 25s)
[2021/06/22 19:45:00] [stored_session.go:122] Refreshing 48.675563336s old session cookie for Session{email:sanitized@sanitized.com user:<sanitized_user_id> PreferredUsername: token:true id_token:true created:2021-06-22 19:44:11.324436664 +0000 UTC expires:2021-06-22 20:44:10 +0000 UTC refresh_token:true} (refresh after 25s)
[2021/06/22 19:45:00] [stored_session.go:122] Refreshing 48.675563336s old session cookie for Session{email:sanitized@sanitized.com user:<sanitized_user_id> PreferredUsername: token:true id_token:true created:2021-06-22 19:44:11.324436664 +0000 UTC expires:2021-06-22 20:44:10 +0000 UTC refresh_token:true} (refresh after 25s)
[2021/06/22 19:45:00] [stored_session.go:122] Refreshing 48.675563336s old session cookie for Session{email:sanitized@sanitized.com user:<sanitized_user_id> PreferredUsername: token:true id_token:true created:2021-06-22 19:44:11.324436664 +0000 UTC expires:2021-06-22 20:44:10 +0000 UTC refresh_token:true} (refresh after 25s)
[2021/06/22 19:45:00] [internal_util.go:69] 200 GET https://www.googleapis.com/oauth2/v1/tokeninfo?access_token=<sanitized_token>... {
  "issued_to": "sanitized.apps.googleusercontent.com",
  "audience": "sanitized.apps.googleusercontent.com",
  "user_id": "<sanitized_user_id>",
  "scope": "https://www.googleapis.com/auth/userinfo.profile https://www.googleapis.com/auth/userinfo.email openid",
  "expires_in": 3550,
  "email": "sanitized@sanitized.com",
  "verified_email": true,
  "access_type": "offline"
}```

iliketoprogram14 on Jun 22, 2021

I’m also seeing this issue when I enabled this to test when setting the refresh time to 1m. I’m using haproxy in front, TimWolla/haproxy-auth-request. I never see a set-cookie header in the response when logging all the auth response headers in the lua file

weikinhuang on Sep 13, 2020