vouch proxy logs

config.yml

vouch:
  headers:   
    idtoken: X-Vouch-IdP-IdToken
    claims:
      - sub
      - unique_name
      - name
      - email
      - groups

  testing: false
  logLevel: debug

  allowAllUsers: true

  cookie:
    secure: true
    domain: xxxx.xxxxxxx.xxxxx.xxxxxx

oauth:
  provider: azure
  client_id: d7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxa6
  client_secret: xxx
  auth_url: https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/authorize
  token_url: https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/token
  user_info_url: https://graph.microsoft.com/oidc/userinfo
  scopes:
    - openid
    - email
    - profile
  callback_url: https://vouch.xxxx.xxxxxxx.xxxxx.xxxxxx/auth
  azure_token: id_token

vouch.log

{"level":"debug","ts":1620111186.1095536,"msg":"open /config/secret: no such file or directory"}
{"level":"info","ts":1620111186.1096017,"msg":"jwt.secret not found in /config/secret"}
{"level":"warn","ts":1620111186.1096077,"msg":"generating random jwt.secret and storing it in /config/secret"}
{"level":"debug","ts":1620111186.1096282,"msg":"open /config/secret: read-only file system"}
{"level":"warn","ts":1620111186.1096332,"msg":"generating random session.key"}
{"level":"info","ts":1620111186.1097596,"msg":"configuring Azure OAuth"}
{"level":"info","ts":1620111186.1098003,"msg":"Using Azure Token: id_token"}
{"level":"info","ts":1620111186.109901,"msg":"configuring azure OAuth with Endpoint https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/authorize"}
{"level":"info","ts":1620111186.109937,"msg":"Vouch.header.claims sub will be forwarded downstream in the Header X-Vouch-IdP-Claims-Sub"}
{"level":"debug","ts":1620111186.1099443,"msg":"nginx will populate the variable $auth_resp_x_vouch_idp_claims_sub"}
{"level":"info","ts":1620111186.1099515,"msg":"Vouch.header.claims unique_name will be forwarded downstream in the Header X-Vouch-IdP-Claims-Unique-Name"}
{"level":"debug","ts":1620111186.109957,"msg":"nginx will populate the variable $auth_resp_x_vouch_idp_claims_unique_name"}
{"level":"info","ts":1620111186.1099627,"msg":"Vouch.header.claims name will be forwarded downstream in the Header X-Vouch-IdP-Claims-Name"}
{"level":"debug","ts":1620111186.1099682,"msg":"nginx will populate the variable $auth_resp_x_vouch_idp_claims_name"}
{"level":"info","ts":1620111186.109974,"msg":"Vouch.header.claims email will be forwarded downstream in the Header X-Vouch-IdP-Claims-Email"}
{"level":"debug","ts":1620111186.1099796,"msg":"nginx will populate the variable $auth_resp_x_vouch_idp_claims_email"}
{"level":"info","ts":1620111186.1099856,"msg":"Vouch.header.claims groups will be forwarded downstream in the Header X-Vouch-IdP-Claims-Groups"}
{"level":"debug","ts":1620111186.1100154,"msg":"nginx will populate the variable $auth_resp_x_vouch_idp_claims_groups"}
{"level":"debug","ts":1620111186.110034,"msg":"cfg.RootDir: /"}
{"level":"debug","ts":1620111186.1101975,"msg":"viper settings map[oauth:map[auth_url:https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/authorize azure_token:id_token callback_url:https://vouch.xxxx.xxxxxxx.xxxxxx.xxxxxx/auth client_id:d7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxa6 client_secret:xxx provider:azure scopes:[openid email profile] token_url:https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/token user_info_url:https://graph.microsoft.com/oidc/userinfo] vouch:map[allowallusers:true cookie:map[domain:xxx secure:true] headers:map[claims:[sub unique_name name email groups] idtoken:X-Vouch-IdP-IdToken] loglevel:debug testing:false]]"}
{"level":"debug","ts":1620111186.1102378,"msg":"cfg.GenOauth &{Provider:azure ClientID:d7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxa6 ClientSecret:xxx AuthURL:https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/authorize TokenURL:https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/token LogoutURL: RedirectURL:https://vouch.xxxx.xxxxxxx.xxxxx.xxxxxx/auth RedirectURLs:[] Scopes:[openid email profile] UserInfoURL:https://graph.microsoft.com/oidc/userinfo UserTeamURL: UserOrgURL: PreferredDomain: AzureToken:id_token CodeChallengeMethod:S256}"}
{"level":"debug","ts":1620111186.1102521,"msg":"vouch.jwt.secret is 44 characters long"}
{"level":"debug","ts":1620111186.110256,"msg":"vouch.session.key is 44 characters long"}
{"level":"info","ts":1620111186.110283,"msg":"jwtcache: the returned headers for a valid jwt will be cached for 20 minutes"}
{"level":"debug","ts":1620111186.1102893,"msg":"responses.Configure() attempting to parse templates with cfg.RootDir: /"}
{"level":"debug","ts":1620111186.1104789,"msg":"checking availability of tcp port: 0.0.0.0:9090"}
{"level":"info","ts":1620111186.1106625,"msg":"starting Vouch Proxy","version":"6d8b79a","buildtime":"2021-05-03T21:36:06Z","buildhost":"localhost","branch":"azureadv2","semver":"v0.6.6-ADFS-02","listen":"http://0.0.0.0:9090","tls":false,"oauth.provider":"azure"}
{"level":"debug","ts":1620111186.1108563,"msg":"serving static files from /static"}
{"level":"debug","ts":1620112021.0709674,"msg":"/validate"}
{"level":"error","ts":1620112021.071004,"msg":"no jwt found in request"}
{"level":"debug","ts":1620112021.0710225,"msg":"setting the cookie domain to xxxx.xxxxxxx.xxxxx.xxxxxx"}
{"level":"debug","ts":1620112021.0710332,"msg":"CaptureWriter.Write set w.StatusCode 401"}
{"level":"info","ts":1620112021.0711982,"msg":"|401|  142.501µs /validate","statusCode":401,"request":1,"latency":0.000142501,"avgLatency":0.000142501,"ipPort":"10.10.192.145:51830","method":"GET","host":"vouch.xxxx.xxxxxxx.xxxxx.xxxxxx","path":"/validate","referer":""}
{"level":"debug","ts":1620112021.1580112,"msg":"/login"}
{"level":"debug","ts":1620112021.1580439,"msg":"setting the cookie domain to xxxx.xxxxxxx.xxxxx.xxxxxx"}
{"level":"debug","ts":1620112021.1581023,"msg":"session state set to 2bwWkaEfd6aP2wbePG7CrDQ53ZqWJm7x"}
{"level":"debug","ts":1620112021.1581628,"msg":"Login url param normalized to 'https://debug.xxxx.xxxxxxx.xxxxx.xxxxxx/'"}
{"level":"debug","ts":1620112021.158183,"msg":"session requestedURL set to https://debug.xxxx.xxxxxxx.xxxxx.xxxxxx/"}
{"level":"debug","ts":1620112021.1581888,"msg":"Adding code challenge"}
{"level":"debug","ts":1620112021.1582265,"msg":"saving session with failcount 1"}
{"level":"debug","ts":1620112021.1590617,"msg":"redirecting to oauthURL https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/oauth2/v2.0/authorize?client_id=d7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxa6&code_challenge=K-cOzTK9YtMO4oKs5FhY2M_WJTXO4MUi0p1xaQqT57I&code_challenge_method=S256&redirect_uri=https%3A%2F%2Fvouch.xxxx.xxxxxxx.xxxxx.xxxxxx%2Fauth&response_type=code&scope=openid+email+profile&state=2bwWkaEfd6aP2wbePG7CrDQ53ZqWJm7x"}
{"level":"debug","ts":1620112021.1590924,"msg":"CaptureWriter.Write set w.StatusCode 302"}
{"level":"info","ts":1620112021.1592376,"msg":"|302| 1.124208ms /login","statusCode":302,"request":2,"latency":0.001124208,"avgLatency":0.000633354,"ipPort":"10.10.192.80:37102","method":"GET","host":"vouch.xxxx.xxxxxxx.xxxxx.xxxxxx","path":"/login","referer":""}
{"level":"debug","ts":1620112038.1605127,"msg":"/auth"}
{"level":"debug","ts":1620112038.160628,"msg":"CaptureWriter.Write set w.StatusCode 302"}
{"level":"info","ts":1620112038.1608222,"msg":"|302|  140.401µs /auth","statusCode":302,"request":3,"latency":0.000140401,"avgLatency":0.000469037,"ipPort":"10.10.192.80:37344","method":"GET","host":"vouch.xxxx.xxxxxxx.xxxxx.xxxxxx","path":"/auth","referer":"https://login.microsoftonline.com/"}
{"level":"debug","ts":1620112038.1796296,"msg":"/auth/{state}/"}
{"level":"debug","ts":1620112038.4633744,"msg":"ptokens: accessToken length: 2483, IdToken length: 1663"}
{"level":"debug","ts":1620112038.463466,"msg":"azure GetUserInfo: getting user info from token: {\"aud\":\"d7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxa6\",\"iss\":\"https://login.microsoftonline.com/c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70/v2.0\",\"iat\":1620111738,\"nbf\":1620111738,\"exp\":1620115638,\"aio\":\"AUQAu/8TAAAARxmTJnRKhOhI8IYz4o3bCla6Y5xqf6mxanA//TWAcgDsqgG6U3bLG6mW3q3PeSzihRn6cwp1+12k5aGwjktOtw==\",\"email\":\"a.m@example.com\",\"groups\":[\"6802e0ac-30cf-43af-970f-c673e770a6a6\",\"d2004cca-7d8f-4abb-8780-c0be7ef455c6\"],\"idp\":\"https://sts.windows.net/c9d5f7f8-284b-4cbb-9b7f-fdc3dd75620c/\",\"name\":\"A. M.\",\"oid\":\"0a58c0fe-0603-4970-b36c-963d036da489\",\"preferred_username\":\"a.m@example.com\",\"rh\":\"0.ATkAPSiqx9xQ3EGtFBBlJdQrcLb51Nc6lKdCuBBTK-REjKY5ADU.\",\"sub\":\"xxxxx\",\"tid\":\"c7xxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx70\",\"uti\":\"HxtcnX2KdU2OYiueQVQnAQ\",\"ver\":\"2.0\",\"wids\":[\"62e90394-69f5-4237-9190-012177145e10\",\"b79fbf4d-3ef9-4689-8143-76b194e85509\"]}"}
{"level":"info","ts":1620112038.4635847,"msg":"azure GetUserInfo: User: &{Username:a.m@example.com Name:A. M. Email:a.m@example.com CreatedOn:0 LastUpdate:0 ID:0 TeamMemberships:[]}"}
{"level":"debug","ts":1620112038.4636164,"msg":"/auth/{state}/ Claims from userinfo: {Claims:map[email:a.m@example.com groups:[6802e0ac-30cf-43af-970f-c673e770a6a6 d2004cca-7d8f-4abb-8780-c0be7ef455c6] name:A. M. sub:xxxxx]}"}
{"level":"debug","ts":1620112038.463626,"msg":"verifyUser: Success! skipping verification, cfg.Cfg.AllowAllUsers is true"}
{"level":"debug","ts":1620112038.4636357,"msg":"token created, expires: 1620126438 diff from now: 14400"}
{"level":"debug","ts":1620112038.4643128,"msg":"token compressed: was 2817 bytes, now 2612"}
{"level":"debug","ts":1620112038.464337,"msg":"setting the cookie domain to xxxx.xxxxxxx.xxxxx.xxxxxx"}
{"level":"debug","ts":1620112038.464503,"msg":"CaptureWriter.Write set w.StatusCode 302"}
{"level":"info","ts":1620112038.4646454,"msg":"|302| 284.92168ms /auth/2bwWkaEfd6aP2wbePG7CrDQ53ZqWJm7x/","statusCode":302,"request":4,"latency":0.28492168,"avgLatency":0.071582197,"ipPort":"10.10.192.80:37344","method":"GET","host":"vouch.xxxx.xxxxxxx.xxxxx.xxxxxx","path":"/auth/2bwWkaEfd6aP2wbePG7CrDQ53ZqWJm7x/","referer":"https://login.microsoftonline.com/"}
{"level":"debug","ts":1620112038.5996284,"msg":"jwt found in cookie"}
{"level":"debug","ts":1620112038.599694,"msg":"/validate"}
{"level":"debug","ts":1620112038.599704,"msg":"jwt found in cookie"}
{"level":"debug","ts":1620112038.5997148,"msg":"tokenString length: 2612"}
{"level":"debug","ts":1620112038.5999458,"msg":"decompressed tokenString length 2817"}
{"level":"debug","ts":1620112038.6001701,"msg":"*ptokenCLaims: {a.m@example.com map[email:a.m@example.com groups:[6802e0ac-30cf-43af-970f-c673e770a6a6 d2004cca-7d8f-4abb-8780-c0be7ef455c6] name:A. M. sub:xxxxx]  eyJxxx {xxxx.xxxxxxx.xxxxx.xxxxxx 1620126438  0 Vouch 0 }}"}
{"level":"debug","ts":1620112038.6002204,"msg":"Found claims in config, finding specific keys..."}
{"level":"debug","ts":1620112038.6002283,"msg":"Found matching claim key: email"}
{"level":"debug","ts":1620112038.6002376,"msg":"Adding header for claim email - X-Vouch-IdP-Claims-Email: a.m@example.com"}
{"level":"debug","ts":1620112038.600243,"msg":"Found matching claim key: groups"}
{"level":"debug","ts":1620112038.6002517,"msg":"Adding header for claim groups - X-Vouch-IdP-Claims-Groups: [6802e0ac-30cf-43af-970f-c673e770a6a6 d2004cca-7d8f-4abb-8780-c0be7ef455c6]"}
{"level":"debug","ts":1620112038.600261,"msg":"Found matching claim key: name"}
{"level":"debug","ts":1620112038.600267,"msg":"Adding header for claim name - X-Vouch-IdP-Claims-Name: A. M."}
{"level":"debug","ts":1620112038.6002722,"msg":"Found matching claim key: sub"}
{"level":"debug","ts":1620112038.6002774,"msg":"Adding header for claim sub - X-Vouch-IdP-Claims-Sub: xxxxx"}
{"level":"debug","ts":1620112038.600317,"msg":"response header","all headers":{"X-Vouch-Idp-Claims-Email":["a.m@example.com"],"X-Vouch-Idp-Claims-Groups":["\"6802e0ac-30cf-43af-970f-c673e770a6a6\",\"d2004cca-7d8f-4abb-8780-c0be7ef455c6\""],"X-Vouch-Idp-Claims-Name":["A. M."],"X-Vouch-Idp-Claims-Sub":["xxxxx"],"X-Vouch-Idp-Idtoken":["eyJxxx"],"X-Vouch-Success":["true"],"X-Vouch-User":["a.m@example.com"]}}
{"level":"info","ts":1620112038.6006083,"msg":"|200|  890.206µs /validate","statusCode":200,"request":5,"latency":0.000890206,"avgLatency":0.057443799,"ipPort":"10.10.192.80:37356","method":"GET","host":"vouch.xxxx.xxxxxxx.xxxxx.xxxxxx","path":"/validate","referer":"https://login.microsoftonline.com/"}
{"level":"debug","ts":1620112038.7154725,"msg":"jwt found in cookie"}
{"level":"debug","ts":1620112038.7155104,"msg":"/validate found response headers for jwt in cache"}
{"level":"info","ts":1620112038.7156184,"msg":"|200|   83.401µs /validate","statusCode":200,"request":6,"latency":0.000083401,"avgLatency":0.047883733,"ipPort":"10.10.192.80:37364","method":"GET","host":"vouch.xxxx.xxxxxxx.xxxxx.xxxxxx","path":"/validate","referer":"https://debug.xxxx.xxxxxxx.xxxxx.xxxxxx/"}