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
- log in via curl, saving the cookie
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.