@@ -5,7 +5,6 @@ import (
55 "errors"
66 "fmt"
77 "html/template"
8− "log"
98 "net"
109 "net/http"
1110 "net/http/httputil"
@@ -16,6 +15,7 @@ import (
1615
1716 "github.com/mbland/hmacauth"
1817 "github.com/pusher/oauth2_proxy/cookie"
18+ "github.com/pusher/oauth2_proxy/logger"
1919 "github.com/pusher/oauth2_proxy/providers"
2020 "github.com/yhat/wsutil"
2121)
@@ -185,7 +185,7 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy {
185185 path := u.Path
186186 switch u.Scheme {
187187 case httpScheme, httpsScheme:
188− log.Printf("mapping path %q => upstream %q", path, u)
188+ logger.Printf("mapping path %q => upstream %q", path, u)
189189 proxy := NewWebSocketOrRestReverseProxy(u, opts, auth)
190190 serveMux.Handle(path, proxy)
191191
@@ -193,7 +193,7 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy {
193193 if u.Fragment != "" {
194194 path = u.Fragment
195195 }
196− log.Printf("mapping path %q => file system %q", path, u.Path)
196+ logger.Printf("mapping path %q => file system %q", path, u.Path)
197197 proxy := NewFileServer(path, u.Path)
198198 serveMux.Handle(path, &UpstreamProxy{path, proxy, nil, nil})
199199 default:
@@ -201,7 +201,7 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy {
201201 }
202202 }
203203 for _, u := range opts.CompiledRegex {
204− log.Printf("compiled skip-auth-regex => %q", u)
204+ logger.Printf("compiled skip-auth-regex => %q", u)
205205 }
206206
207207 redirectURL := opts.redirectURL
@@ -209,20 +209,20 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy {
209209 redirectURL.Path = fmt.Sprintf("%s/callback", opts.ProxyPrefix)
210210 }
211211
212− log.Printf("OAuthProxy configured for %s Client ID: %s", opts.provider.Data().ProviderName, opts.ClientID)
212+ logger.Printf("OAuthProxy configured for %s Client ID: %s", opts.provider.Data().ProviderName, opts.ClientID)
213213 refresh := "disabled"
214214 if opts.CookieRefresh != time.Duration(0) {
215215 refresh = fmt.Sprintf("after %s", opts.CookieRefresh)
216216 }
217217
218− log.Printf("Cookie settings: name:%s secure(https):%v httponly:%v expiry:%s domain:%s path:%s refresh:%s", opts.CookieName, opts.CookieSecure, opts.CookieHTTPOnly, opts.CookieExpire, opts.CookieDomain, opts.CookiePath, refresh)
218+ logger.Printf("Cookie settings: name:%s secure(https):%v httponly:%v expiry:%s domain:%s path:%s refresh:%s", opts.CookieName, opts.CookieSecure, opts.CookieHTTPOnly, opts.CookieExpire, opts.CookieDomain, opts.CookiePath, refresh)
219219
220220 var cipher *cookie.Cipher
221221 if opts.PassAccessToken || opts.SetAuthorization || opts.PassAuthorization || (opts.CookieRefresh != time.Duration(0)) {
222222 var err error
223223 cipher, err = cookie.NewCipher(secretBytes(opts.CookieSecret))
224224 if err != nil {
225− log.Fatal("cookie-secret error: ", err)
225+ logger.Fatal("cookie-secret error: ", err)
226226 }
227227 }
228228
@@ -425,7 +425,7 @@ func (p *OAuthProxy) makeCookie(req *http.Request, name string, value string, ex
425425 domain = h
426426 }
427427 if !strings.HasSuffix(domain, p.CookieDomain) {
428− log.Printf("Warning: request host is %q but using configured cookie domain of %q", domain, p.CookieDomain)
428+ logger.Printf("Warning: request host is %q but using configured cookie domain of %q", domain, p.CookieDomain)
429429 }
430430 }
431431
@@ -529,7 +529,6 @@ func (p *OAuthProxy) PingPage(rw http.ResponseWriter) {
529529
530530// ErrorPage writes an error response
531531func (p *OAuthProxy) ErrorPage(rw http.ResponseWriter, code int, title string, message string) {
532− log.Printf("ErrorPage %d %s %s", code, title, message)
533532 rw.WriteHeader(code)
534533 t := struct {
535534 Title string
@@ -588,9 +587,10 @@ func (p *OAuthProxy) ManualSignIn(rw http.ResponseWriter, req *http.Request) (st
588587 }
589588 // check auth
590589 if p.HtpasswdFile.Validate(user, passwd) {
591− log.Printf("authenticated %q via HtpasswdFile", user)
590+ logger.PrintAuthf(user, req, logger.AuthSuccess, "Authenticated via HtpasswdFile")
592591 return user, true
593592 }
593+ logger.PrintAuthf(user, req, logger.AuthFailure, "Invalid authentication via HtpasswdFile")
594594 return "", false
595595}
596596
@@ -686,6 +686,7 @@ func (p *OAuthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
686686func (p *OAuthProxy) SignIn(rw http.ResponseWriter, req *http.Request) {
687687 redirect, err := p.GetRedirect(req)
688688 if err != nil {
689+ logger.Printf("Error obtaining redirect: %s", err.Error())
689690 p.ErrorPage(rw, 500, "Internal Error", err.Error())
690691 return
691692 }
@@ -714,12 +715,14 @@ func (p *OAuthProxy) SignOut(rw http.ResponseWriter, req *http.Request) {
714715func (p *OAuthProxy) OAuthStart(rw http.ResponseWriter, req *http.Request) {
715716 nonce, err := cookie.Nonce()
716717 if err != nil {
718+ logger.Printf("Error obtaining nonce: %s", err.Error())
717719 p.ErrorPage(rw, 500, "Internal Error", err.Error())
718720 return
719721 }
720722 p.SetCSRFCookie(rw, req, nonce)
721723 redirect, err := p.GetRedirect(req)
722724 if err != nil {
725+ logger.Printf("Error obtaining redirect: %s", err.Error())
723726 p.ErrorPage(rw, 500, "Internal Error", err.Error())
724727 return
725728 }
@@ -735,24 +738,27 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) {
735738 // finish the oauth cycle
736739 err := req.ParseForm()
737740 if err != nil {
741+ logger.Printf("Error while parsing OAuth2 callback: %s" + err.Error())
738742 p.ErrorPage(rw, 500, "Internal Error", err.Error())
739743 return
740744 }
741745 errorString := req.Form.Get("error")
742746 if errorString != "" {
747+ logger.Printf("Error while parsing OAuth2 callback: %s ", errorString)
743748 p.ErrorPage(rw, 403, "Permission Denied", errorString)
744749 return
745750 }
746751
747752 session, err := p.redeemCode(req.Host, req.Form.Get("code"))
748753 if err != nil {
749− log.Printf("%s error redeeming code %s", remoteAddr, err)
754+ logger.Printf("Error redeeming code during OAuth2 callback: %s ", errorString)
750755 p.ErrorPage(rw, 500, "Internal Error", "Internal Error")
751756 return
752757 }
753758
754759 s := strings.SplitN(req.Form.Get("state"), ":", 2)
755760 if len(s) != 2 {
761+ logger.Printf("Error while parsing OAuth2 state: invalid length")
756762 p.ErrorPage(rw, 500, "Internal Error", "Invalid State")
757763 return
758764 }
@@ -760,12 +766,13 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) {
760766 redirect := s[1]
761767 c, err := req.Cookie(p.CSRFCookieName)
762768 if err != nil {
769+ logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Invalid authentication via OAuth2: unable too obtain CSRF cookie")
763770 p.ErrorPage(rw, 403, "Permission Denied", err.Error())
764771 return
765772 }
766773 p.ClearCSRFCookie(rw, req)
767774 if c.Value != nonce {
768− log.Printf("%s csrf token mismatch, potential attack", remoteAddr)
775+ logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Invalid authentication via OAuth2: csrf token mismatch, potential attack")
769776 p.ErrorPage(rw, 403, "Permission Denied", "csrf failed")
770777 return
771778 }
@@ -776,16 +783,16 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) {
776783
777784 // set cookie, or deny
778785 if p.Validator(session.Email) && p.provider.ValidateGroup(session.Email) {
779− log.Printf("%s authentication complete %s", remoteAddr, session)
786+ logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Authenticated via OAuth2: %s", session)
780787 err := p.SaveSession(rw, req, session)
781788 if err != nil {
782− log.Printf("%s %s", remoteAddr, err)
789+ logger.Printf("%s %s", remoteAddr, err)
783790 p.ErrorPage(rw, 500, "Internal Error", "Internal Error")
784791 return
785792 }
786793 http.Redirect(rw, req, redirect, 302)
787794 } else {
788− log.Printf("%s Permission Denied: %q is unauthorized", remoteAddr, session.Email)
795+ logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Invalid authentication via OAuth2: unauthorized")
789796 p.ErrorPage(rw, 403, "Permission Denied", "Invalid Account")
790797 }
791798}
@@ -827,16 +834,16 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int
827834
828835 session, sessionAge, err := p.LoadCookiedSession(req)
829836 if err != nil {
830− log.Printf("%s %s", remoteAddr, err)
837+ logger.Printf("Error loading cookied session: %s", err)
831838 }
832839 if session != nil && sessionAge > p.CookieRefresh && p.CookieRefresh != time.Duration(0) {
833− log.Printf("%s refreshing %s old session cookie for %s (refresh after %s)", remoteAddr, sessionAge, session, p.CookieRefresh)
840+ logger.Printf("Refreshing %s old session cookie for %s (refresh after %s)", sessionAge, session, p.CookieRefresh)
834841 saveSession = true
835842 }
836843
837844 var ok bool
838845 if ok, err = p.provider.RefreshSessionIfNeeded(session); err != nil {
839− log.Printf("%s removing session. error refreshing access token %s %s", remoteAddr, err, session)
846+ logger.Printf("%s removing session. error refreshing access token %s %s", remoteAddr, err, session)
840847 clearSession = true
841848 session = nil
842849 } else if ok {
@@ -845,7 +852,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int
845852 }
846853
847854 if session != nil && session.IsExpired() {
848− log.Printf("%s removing session. token expired %s", remoteAddr, session)
855+ logger.Printf("Removing session: token expired %s", session)
849856 session = nil
850857 saveSession = false
851858 clearSession = true
@@ -853,7 +860,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int
853860
854861 if saveSession && !revalidated && session != nil && session.AccessToken != "" {
855862 if !p.provider.ValidateSessionState(session) {
856− log.Printf("%s removing session. error validating %s", remoteAddr, session)
863+ logger.Printf("Removing session: error validating %s", session)
857864 saveSession = false
858865 session = nil
859866 clearSession = true
@@ -861,7 +868,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int
861868 }
862869
863870 if session != nil && session.Email != "" && !p.Validator(session.Email) {
864− log.Printf("%s Permission Denied: removing session %s", remoteAddr, session)
871+ logger.Printf(session.Email, req, logger.AuthFailure, "Invalid authentication via session: removing session %s", session)
865872 session = nil
866873 saveSession = false
867874 clearSession = true
@@ -870,7 +877,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int
870877 if saveSession && session != nil {
871878 err = p.SaveSession(rw, req, session)
872879 if err != nil {
873− log.Printf("%s %s", remoteAddr, err)
880+ logger.PrintAuthf(session.Email, req, logger.AuthError, "Save session error %s", err)
874881 return http.StatusInternalServerError
875882 }
876883 }
@@ -882,7 +889,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int
882889 if session == nil {
883890 session, err = p.CheckBasicAuth(req)
884891 if err != nil {
885− log.Printf("%s %s", remoteAddr, err)
892+ logger.Printf("Error during basic auth validation: %s", err)
886893 }
887894 }
888895
@@ -958,10 +965,11 @@ func (p *OAuthProxy) CheckBasicAuth(req *http.Request) (*providers.SessionState,
958965 return nil, fmt.Errorf("invalid format %s", b)
959966 }
960967 if p.HtpasswdFile.Validate(pair[0], pair[1]) {
961− log.Printf("authenticated %q via basic auth", pair[0])
968+ logger.PrintAuthf(pair[0], req, logger.AuthSuccess, "Authenticated via basic auth and HTpasswd File")
962969 return &providers.SessionState{User: pair[0]}, nil
963970 }
964− return nil, fmt.Errorf("%s not in HtpasswdFile", pair[0])
971+ logger.PrintAuthf(pair[0], req, logger.AuthFailure, "Invalid authentication via basic auth: not in Htpasswd File")
972+ return nil, nil
965973}
966974
967975// isAjax checks if a request is an ajax request