{"level":"info","ts":1701980592.5301375,"msg":"Copyright 2020-2022 the Vouch Proxy Authors"} {"level":"warn","ts":1701980592.5301664,"msg":"Vouch Proxy is free software with ABSOLUTELY NO WARRANTY."} {"level":"warn","ts":1701980592.5301702,"msg":"set cfg.RootDir from VOUCH_ROOT env var: /"} {"level":"info","ts":1701980592.5309818,"msg":"jwt.secret read from /config/secret"} {"level":"warn","ts":1701980592.530992,"msg":"generating random session.key"} {"level":"info","ts":1701980592.531075,"msg":"configuring oidc OAuth with Endpoint https://auth.faked.org/application/o/authorize/"} {"level":"debug","ts":1701980592.5310807,"msg":"cfg.RootDir: /"} {"level":"debug","ts":1701980592.5311017,"msg":"Cfg {LogLevel:debug Listen:0.0.0.0 Port:9090 SocketMode:432 SocketGroup: DocumentRoot: WriteTimeout:15 ReadTimeout:15 IdleTimeout:15 Domains:[faked.org] WhiteList:[] TeamWhiteList:[] AllowAllUsers:false PublicAccess:false TLS:{Cert: Key: Profile:intermediate} JWT:{SigningMethod:HS256 MaxAge:240 Issuer:Vouch Secret:XXXXXXXX PrivateKeyFile: PublicKeyFile: Compress:true} Cookie:{Name:VouchCookie Domain: Secure:true HTTPOnly:true MaxAge:240 SameSite:} Headers:{JWT:X-Vouch-Token User:X-Vouch-User QueryString:access_token Redirect:X-Vouch-Requested-URI Success:X-Vouch-Success Error:X-Vouch-Error ClaimHeader:X-Vouch-IdP-Claims- Claims:[] AccessToken: IDToken: ClaimsCleaned:map[]} Session:{Name:VouchSession MaxAge:5 Key:XXXXXXXX} TestURL: TestURLs:[] Testing:true LogoutRedirectURLs:[https://auth.faked.org/application/o/revoke/]}"} {"level":"debug","ts":1701980592.5311155,"msg":"cfg.GenOauth {Provider:oidc ClientID:12345678 ClientSecret:XXXXXXXX AuthURL:https://auth.faked.org/application/o/authorize/ TokenURL:https://auth.faked.org/application/o/token/ LogoutURL:https://auth.faked.org/application/o/nginx/end-session/ RedirectURL:https://sso.faked.org/auth RedirectURLs:[] RelyingPartyId: Scopes:[openid email profile] Claims: UserInfoURL:https://auth.faked.org/application/o/userinfo/ UserTeamURL: UserOrgURL: PreferredDomain: AzureToken: CodeChallengeMethod:}"} 2023-12-07T20:23:12.531Z INFO testing: true, using development console logger 2023-12-07T20:23:12.531Z DEBUG vouch.jwt.secret is 44 characters long 2023-12-07T20:23:12.531Z DEBUG vouch.session.key is 44 characters long 2023-12-07T20:23:12.531Z INFO jwtcache: the returned headers for a valid jwt will be cached for 20 minutes 2023-12-07T20:23:12.531Z DEBUG responses.Configure() attempting to parse embedded templates {"level":"debug","ts":1701980592.5325341,"msg":"checking availability of tcp port: 0.0.0.0:9090"} {"level":"info","ts":1701980592.5327106,"msg":"starting Vouch Proxy","version":"a676feb","buildtime":"2023-01-21T21:47:20Z","uname":"Linux","buildhost":"buildkitsandbox","branch":"HEAD","semver":"v0.39.0","listen":"http://0.0.0.0:9090","tls":false,"document_root":"","oauth.provider":"oidc"} 2023-12-07T20:23:14.678Z DEBUG jwt found in cookie 2023-12-07T20:23:14.678Z DEBUG /validate 2023-12-07T20:23:14.678Z DEBUG jwt found in cookie 2023-12-07T20:23:14.678Z DEBUG tokenString length: 320 2023-12-07T20:23:14.678Z DEBUG decompressed tokenString length 251 2023-12-07T20:23:14.679Z DEBUG *ptokenCLaims: {jan@faked.org map[] {faked.org 1701992417 0 Vouch 0 }} 2023-12-07T20:23:14.679Z DEBUG site rabbitmq.faked.org is found for claims.Audience faked.org 2023-12-07T20:23:14.679Z DEBUG response header {"all headers": {"X-Vouch-Success":["true"],"X-Vouch-User":["jan@faked.org"]}} 2023-12-07T20:23:14.679Z DEBUG tokenString length: 320 2023-12-07T20:23:14.679Z DEBUG decompressed tokenString length 251 2023-12-07T20:23:14.679Z DEBUG *ptokenCLaims: {jan@faked.org map[] {faked.org 1701992417 0 Vouch 0 }} 2023-12-07T20:23:14.679Z INFO |200| 947.96µs /validate {"statusCode": 200, "request": 1, "latency": "947.96µs", "avgLatency": "947.96µs", "ipPort": "172.17.0.1:33642", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:14.694Z DEBUG jwt found in cookie 2023-12-07T20:23:14.694Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:14.694Z INFO |200| 89.12µs /validate {"statusCode": 200, "request": 2, "latency": "89.12µs", "avgLatency": "518.54µs", "ipPort": "172.17.0.1:33656", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:19.746Z DEBUG jwt found in cookie 2023-12-07T20:23:19.746Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:19.746Z INFO |200| 61.066µs /validate {"statusCode": 200, "request": 3, "latency": "61.066µs", "avgLatency": "366.049µs", "ipPort": "172.17.0.1:34538", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:19.760Z DEBUG jwt found in cookie 2023-12-07T20:23:19.760Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:19.760Z INFO |200| 51.808µs /validate {"statusCode": 200, "request": 4, "latency": "51.808µs", "avgLatency": "287.489µs", "ipPort": "172.17.0.1:34552", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:22.513Z DEBUG jwt found in cookie 2023-12-07T20:23:22.513Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.513Z INFO |200| 73.269µs /validate {"statusCode": 200, "request": 5, "latency": "73.269µs", "avgLatency": "244.645µs", "ipPort": "172.17.0.1:34554", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": ""} 2023-12-07T20:23:22.565Z DEBUG jwt found in cookie 2023-12-07T20:23:22.565Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.565Z DEBUG jwt found in cookie 2023-12-07T20:23:22.565Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.565Z INFO |200| 85.191µs /validate {"statusCode": 200, "request": 6, "latency": "85.191µs", "avgLatency": "218.07µs", "ipPort": "172.17.0.1:34564", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:22.565Z INFO |200| 182.537µs /validate {"statusCode": 200, "request": 7, "latency": "182.537µs", "avgLatency": "212.994µs", "ipPort": "172.17.0.1:34576", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:22.565Z DEBUG jwt found in cookie 2023-12-07T20:23:22.565Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.565Z INFO |200| 133.905µs /validate {"statusCode": 200, "request": 8, "latency": "133.905µs", "avgLatency": "203.108µs", "ipPort": "172.17.0.1:34590", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:22.765Z DEBUG jwt found in cookie 2023-12-07T20:23:22.765Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.765Z INFO |200| 126.971µs /validate {"statusCode": 200, "request": 9, "latency": "126.971µs", "avgLatency": "194.649µs", "ipPort": "172.17.0.1:34592", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:22.785Z DEBUG jwt found in cookie 2023-12-07T20:23:22.785Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.785Z DEBUG jwt found in cookie 2023-12-07T20:23:22.785Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.785Z INFO |200| 52.059µs /validate {"statusCode": 200, "request": 11, "latency": "52.059µs", "avgLatency": "177.471µs", "ipPort": "172.17.0.1:34606", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:22.785Z INFO |200| 148.272µs /validate {"statusCode": 200, "request": 11, "latency": "148.272µs", "avgLatency": "177.471µs", "ipPort": "172.17.0.1:34600", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:22.796Z DEBUG jwt found in cookie 2023-12-07T20:23:22.796Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:22.796Z INFO |200| 56.788µs /validate {"statusCode": 200, "request": 12, "latency": "56.788µs", "avgLatency": "167.415µs", "ipPort": "172.17.0.1:34622", "method": "GET", "host": "elastic.faked.org", "path": "/validate", "referer": "https://elastic.faked.org/"} 2023-12-07T20:23:24.960Z DEBUG jwt found in cookie 2023-12-07T20:23:24.960Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:24.960Z INFO |200| 73.699µs /validate {"statusCode": 200, "request": 13, "latency": "73.699µs", "avgLatency": "160.207µs", "ipPort": "172.17.0.1:34628", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:24.975Z DEBUG jwt found in cookie 2023-12-07T20:23:24.975Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:24.975Z INFO |200| 80.283µs /validate {"statusCode": 200, "request": 14, "latency": "80.283µs", "avgLatency": "154.499µs", "ipPort": "172.17.0.1:34640", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:30.067Z DEBUG jwt found in cookie 2023-12-07T20:23:30.067Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:30.067Z INFO |200| 83.589µs /validate {"statusCode": 200, "request": 15, "latency": "83.589µs", "avgLatency": "149.772µs", "ipPort": "172.17.0.1:52274", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"} 2023-12-07T20:23:30.081Z DEBUG jwt found in cookie 2023-12-07T20:23:30.081Z DEBUG /validate found response headers for jwt in cache 2023-12-07T20:23:30.081Z INFO |200| 80.443µs /validate {"statusCode": 200, "request": 16, "latency": "80.443µs", "avgLatency": "145.439µs", "ipPort": "172.17.0.1:52284", "method": "GET", "host": "rabbitmq.faked.org", "path": "/validate", "referer": "https://rabbitmq.faked.org/"}