Oauth2-proxy: Cookie Refresh logging exposes too much information

[idntfy]

Background

• We are updating oauth2-proxy from 2.2.0 (!) to 5.1.1 and one of the behavioral changes bothers us much more than others.
• Together with the update we're migrating to OIDC provider instead of google + we're using extra issuers. The configuration works well in our development environments for about 4 months already, but due to this issue we're resistant to promote it to prod.

Issue

Comparing to the older version, new one logs session information, or rather raw decoded JWT token. You may argue that according to JWT it is not private information, however:

• it makes the data very easily available than otherwise.
• it puts it to stderr. We already don't log stdout into our ELK, but we do want to see errors. This is not an error.
• it creates noise and takes space.
• it logs part of private token. It seems it is some kind of request-response logger - who knows what else it can expose? What if with the next version it will stop truncating the private token? What if the response will contain something private? There are risks down the road even if it is not the case now.

Expected Behavior

This is what 2.2.0 version logs in this situation:

2020/05/18 23:16:53 google.go:277: refreshed access token Session{[email protected] token:true expires:2020-05-19 00:16:52 +0000 UTC refresh_token:true} (expired on 2020-05-18 23:09:56 +0000 UTC)

Current Behavior

This is what 5.1.1 version logs in this situation:

[2020/05/18 23:12:38] [oauthproxy.go:876] Refreshing 21m14.780532319s old session cookie for Session{email:[email protected] user:102924XXX22720 PreferredUsername: token:true id_token:true created:2020-05-18 22:51:23.219467681 +0000 UTC expires:2020-05-18 23:51:22 +0000 UTC} (refresh after 1m0s)
[2020/05/18 23:12:38] [internal_util.go:67] 200 GET https://www.googleapis.com/oauth2/v1/tokeninfo?access_token=ya29.a0AfH6SMDXXXq6IvrkXYecGxAXXXXaZyxUl94DVJjImzcsyBNf9wkyn_nJ... {
  "issued_to": "45XXXXXtaneipirXXX1.apps.googleusercontent.com",
  "audience": "45XXXXXtaneipirXXX1.apps.googleusercontent.com",
  "user_id": "102924XXXXX22720",
  "scope": "https://www.googleapis.com/auth/userinfo.profile https://www.googleapis.com/auth/userinfo.email https://www.googleapis.com/auth/spreadsheets.readonly openid",
  "expires_in": 2323,
  "email": "[email protected]",
  "verified_email": true,
  "access_type": "offline"
}

Possible Solution

• Proposal 1 - Stop logging session.
• Proposal 2 - Make it configurable with the ability to disable.
• Proposal 3 - Make it dependable on --auth-logging parameter.

Steps to Reproduce

1. Run oauth-proxy with -cookie-refresh=1m for the sake of example.
2. Log in.
3. Wait 1 minute.
4. Refresh the page. See logs.

Your Environment

• Version used: 5.1.1, official docker image.
• Docker compose:

    command: [
      "-http-address=http://0.0.0.0:80",
      "-redirect-url=http://localhost:8080/oauth2/callback",
      "-upstream=http://echo:8080/",
      "-email-domain=XXX.co",,
      "-oidc-issuer-url=https://accounts.google.com",
      "-skip-jwt-bearer-tokens=true",
      "-extra-jwt-issuers=XXX",
      "-pass-authorization-header=true",
      "-client-id=XXX",
      "-client-secret=XXX",
      "-cookie-secret=XXX",
      "-cookie-domain=localhost:8080",
      "-cookie-secure=false",
      "-cookie-refresh=1m",
      "-skip-auth-regex=.*/ping$$",
      "-skip-provider-button=false",
      "-pass-access-token=true",
      "-pass-user-headers=true",
      "-pass-basic-auth=false",
      "-skip-auth-preflight=true",
      "-scope=profile email https://www.googleapis.com/auth/spreadsheets.readonly"
    ]

[JoelSpeed]

I think there's several issues at play here

1) A lack of levelled logging: I would like to have this, we need to only log certain log lines if users request detailed logs

2) Logs all go to stderr: We should only be logging errors to stderr, everything else should log to stdout by default

3) I think your config may be slightly incorrect: I was a bit confused when you said you were seeing this behaviour with oidc, the code that produces that log line isn't called by the OIDC provider flow. Try adding --provider=oidc to your options and see if that removes this particular issue, I think the auth is still using the old google provider because you haven't specified which provider to use

[idntfy]

Re 3 - nice catch! Yes, adding -provider=oidc removed the excessive request/response logging, seemingly everything works the same way from UX perspective. Thank you very much!

• However, when testing further I ran into #490 - I'll follow up on that separately there.
• Re 1 and 2 - they are being discussed in some other issues too such as #475.

Soo @JoelSpeed I would say you solved my immediate issue and others are tracked already - I'm good if we close this, will leave it to you. Thanks!

[JoelSpeed]

Great! I'll take a look at your new issue soon