sso-auth: improve logging when validateRedirectURI fails

[weeco]

I just tried to setup the SSO application on my kubernetes cluster. Unfortunately I ran into this screen (Invalid redirect parameter):

Hence I followed the logs of my proxy and auth containers, trying to get more information about what is going wrong there. The following logs were produced when I requested my protected service (grafana.service.int.mydomain.com):

Buzzfeed SSO auth:

{"action":"ping","http_status":200,"level":"info","msg":"","proxy_host":"","remote_address":"10.0.3.1:59424","request_duration":92.926993,"request_method":"GET","request_uri":"/ping","service":"sso-authenticator","time":"2018-10-26 08:49:18.10268","user":"","user_agent":"kube-probe/1.10+"}
{"http_status":400,"level":"info","msg":"error page","page_message":"Invalid redirect parameter","page_title":"Bad Request","service":"sso-authenticator","time":"2018-10-26 08:49:20.10268"}
{"action":"sign_in","http_status":400,"level":"info","msg":"","proxy_host":"grafana.service.int.mydomain.com","remote_address":"x.x.x.x","request_duration":0.300514,"request_method":"GET","request_uri":"/sign_in?client_id=xxxxxxxx%3D\u0026redirect_uri=https%3A%2F%2Fgrafana.service.int.mydomain.com%2Foauth2%2Fcallback\u0026response_type=code\u0026scope=\u0026sig=agEpu9YxxxxxxxxxxxxxxcMhKwu5M%3D\u0026state=aUcD-ZEXALKO68Ly2xxxxxxxxxxxx7JfZDibaqwvXEt6fWQ04ugfHLyeWoy4YqrpwsYkTUdM0x17y8Jf4c-VTrv-OkST6vXAtdWkAHiNuChZ5HLjZdXSdEHHQcA7uePz6jTblPVLsv3H5jxz81yb449dGHg\u0026ts=1540543760","service":"sso-authenticator","time":"2018-10-26 08:49:20.10268","user":"","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36"}
{"action":"static","http_status":200,"level":"info","msg":"","proxy_host":"","remote_address":"x.x.x.x","request_duration":0.209806,"request_method":"GET","request_uri":"/static/sso.css","service":"sso-authenticator","time":"2018-10-26 08:49:20.10268","user":"","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36"}

**Buzzfeed SSO proxy:***

{"error":"http: named cookie not present","level":"error","msg":"error authenticating user","remote_address":"x.x.x.x","service":"sso-proxy","time":"2018-10-26 08:53:01.10268"}
{"level":"info","msg":"starting OAuth flow","service":"sso-proxy","sign_in_url":{"Scheme":"https","Opaque":"","User":null,"Host":"sso-auth.service.int.mydomain.com","Path":"/sign_in","RawPath":"","ForceQuery":false,"RawQuery":"client_id=xxxxxxxxx0%3D\u0026redirect_uri=https%3A%2F%2Fgrafana.service.int.mydomain.com%2Foauth2%2Fcallback\u0026response_type=code\u0026scope=\u0026sig=RRxxxxxxDdteCAiyJXFI%3D\u0026state=bdn38uuHCGzQfxxxxxx9iRRV7p5Vva\u0026ts=1540543981","Fragment":""},"time":"2018-10-26 08:53:01.10268"}
{"action":"proxy","http_status":302,"level":"info","msg":"","remote_address":"x.x.x.x","request_duration":0.557463,"request_method":"GET","request_uri":"grafana.service.int.mydomain.com/public/img/icons_dark_theme/icon_playlist.svg","service":"sso-proxy","time":"2018-10-26 08:53:01.10268","user":"","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36"}
{"error":"http: named cookie not present","level":"error","msg":"error authenticating user","remote_address":"x.x.x.x","service":"sso-proxy","time":"2018-10-26 08:53:01.10268"}

Question:

How could I investigate this error?

[weeco]

After looking at the code here https://github.com/buzzfeed/sso/blob/master/internal/auth/middleware.go#L106-L124 it seems this issue appears because the validateRedirectURI (which is indeed grafana.service.int.mydomain.com in my request which returns status code 400).

My blind guess is that if !validRedirectURI(redirectURI, p.ProxyRootDomains) returns false, which may happen because redirectURL.Hostname() hasn't set the correct rootDomain or doesn't get the correct redirectUri. Maybe you can log the passed parameters in case this if condition fails?

if strings.HasSuffix(redirectURL.Hostname(), domain)

Additional info: My redirect_uri is set to http://grafana.service.int.mydomain.com/oauth2/callback (surprisingly http and not https?). Any help is appreciated.

[weeco]

Ok I figured it out, indeed my root domain was wrong, but I'd like to propose to log the passed parameters in validateRedirectURI in case

if strings.HasSuffix(redirectURL.Hostname(), domain)

fails. What do you think?

[danbf]

@weeco was just firing up a cluster to try to troubleshoot. think there is anything we could add to https://github.com/buzzfeed/sso/blob/master/docs/quickstart.md or https://medium.com/@while1eq1/single-sign-on-for-internal-apps-in-kubernetes-using-google-oauth-sso-2386a34bc433 to make this more straightforward.

we set http just for the quickstart to simplifiy the setup, in actual practice we use https for our clusters even in dev

[weeco]

@danbf I am trying to achieve the same. I believe some sort of "production checklist" is helpful if you want to keep going with the "demo setup tutorial" to just get it up. However, this issue is primarily about the specific use case if someone accidentially uses a wrong proxyRootDomain. I believe my proposal to add a log message (see my previous comment) would be helpful.

[danbf]

for https support use just leave off COOKIE_SECURE which defaults to true, you will need valid certs!, default values set here: https://github.com/buzzfeed/sso/blob/3a64e696452e2fea5d571e63ad5a53e45694ecd1/internal/auth/options.go#L76 https://github.com/buzzfeed/sso/blob/1662f7cc129421a9d2ac8aff577823bbd3703ec8/internal/proxy/options.go#L71

or explicitly set

          - name: COOKIE_SECURE
            value: "true"

here in the kuberneties quickstart: https://github.com/buzzfeed/sso/blob/cba449199768d18606bdf88b65ca1b8e64448a36/quickstart/kubernetes/sso-auth-deployment.yml#L78-L79 https://github.com/buzzfeed/sso/blob/cba449199768d18606bdf88b65ca1b8e64448a36/quickstart/kubernetes/sso-proxy-deployment.yml#L53-L54

[danbf]

i think there is case for better logging for sure