diff --git a/handlers/handlers.go b/handlers/handlers.go index 7efb54d0..ca57a47a 100644 --- a/handlers/handlers.go +++ b/handlers/handlers.go @@ -13,7 +13,8 @@ import ( "strconv" "strings" - log "github.com/Sirupsen/logrus" + "go.uber.org/zap" + securerandom "github.com/theckman/go-securerandom" "github.com/gorilla/sessions" @@ -49,6 +50,9 @@ var ( // http://www.gorillatoolkit.org/pkg/sessions sessstore = sessions.NewCookieStore([]byte(cfg.Cfg.Session.Key)) + + log = cfg.Cfg.Logger + fastlog = cfg.Cfg.FastLogger ) func init() { @@ -139,7 +143,7 @@ func ClaimsFromJWT(jwt string) (jwtmanager.VouchClaims, error) { // ValidateRequestHandler /validate // TODO this should use the handler interface func ValidateRequestHandler(w http.ResponseWriter, r *http.Request) { - log.Debug("/validate") + fastlog.Debug("/validate") // TODO: collapse all of the `if !cfg.Cfg.PublicAccess` calls // perhaps using an `ok=false` pattern @@ -175,9 +179,8 @@ func ValidateRequestHandler(w http.ResponseWriter, r *http.Request) { } return } - log.WithFields(log.Fields{ - "username": claims.Username, - }).Info("jwt cookie") + fastlog.Info("jwt cookie", + zap.String("username", claims.Username)) if !cfg.Cfg.AllowAllUsers { if !jwtmanager.SiteInClaims(r.Host, &claims) { @@ -194,7 +197,8 @@ func ValidateRequestHandler(w http.ResponseWriter, r *http.Request) { w.Header().Add(cfg.Cfg.Headers.User, claims.Username) w.Header().Add(cfg.Cfg.Headers.Success, "true") - log.WithFields(log.Fields{cfg.Cfg.Headers.User: w.Header().Get(cfg.Cfg.Headers.User)}).Debug("response header") + fastlog.Debug("response header", + zap.String(cfg.Cfg.Headers.User, w.Header().Get(cfg.Cfg.Headers.User))) // good to go!! if cfg.Cfg.Testing { @@ -387,7 +391,7 @@ func CallbackHandler(w http.ResponseWriter, r *http.Request) { errorState := r.URL.Query().Get("error") if errorState != "" { errorDescription := r.URL.Query().Get("error_description") - log.Warning("Error state: ", errorState, ", Error description: ", errorDescription) + log.Warn("Error state: ", errorState, ", Error description: ", errorDescription) w.WriteHeader(http.StatusForbidden) renderIndex(w, "FORBIDDEN: "+errorDescription) return @@ -468,9 +472,9 @@ func getUserInfoFromOpenID(client *http.Client, user *structs.User, ptoken *oaut } defer userinfo.Body.Close() data, _ := ioutil.ReadAll(userinfo.Body) - log.Println("OpenID userinfo body: ", string(data)) + log.Infof("OpenID userinfo body: ", string(data)) if err = json.Unmarshal(data, user); err != nil { - log.Errorln(err) + log.Error(err) return err } user.PrepareUserData() @@ -484,9 +488,9 @@ func getUserInfoFromGoogle(client *http.Client, user *structs.User) error { } defer userinfo.Body.Close() data, _ := ioutil.ReadAll(userinfo.Body) - log.Println("google userinfo body: ", string(data)) + log.Infof("google userinfo body: ", string(data)) if err = json.Unmarshal(data, user); err != nil { - log.Errorln(err) + log.Error(err) return err } user.PrepareUserData() @@ -506,10 +510,10 @@ func getUserInfoFromGitHub(client *http.Client, user *structs.User, ptoken *oaut } defer userinfo.Body.Close() data, _ := ioutil.ReadAll(userinfo.Body) - log.Println("github userinfo body: ", string(data)) + log.Infof("github userinfo body: ", string(data)) ghUser := structs.GitHubUser{} if err = json.Unmarshal(data, &ghUser); err != nil { - log.Errorln(err) + log.Error(err) return err } log.Debug("getUserInfoFromGitHub ghUser") @@ -574,10 +578,10 @@ func getUserInfoFromIndieAuth(r *http.Request, user *structs.User) error { } defer userinfo.Body.Close() data, _ := ioutil.ReadAll(userinfo.Body) - log.Println("indieauth userinfo body: ", string(data)) + log.Infof("indieauth userinfo body: ", string(data)) iaUser := structs.IndieAuthUser{} if err = json.Unmarshal(data, &iaUser); err != nil { - log.Errorln(err) + log.Error(err) return err } iaUser.PrepareUserData() @@ -644,7 +648,7 @@ func getUserInfoFromADFS(r *http.Request, user *structs.User) error { adfsUser := structs.ADFSUser{} json.Unmarshal([]byte(idToken), &adfsUser) - log.Println("adfs adfsUser: ", adfsUser) + log.Infof("adfs adfsUser: ", adfsUser) adfsUser.PrepareUserData() user.Username = adfsUser.Username diff --git a/main.go b/main.go index 68060d03..3b0e4a71 100644 --- a/main.go +++ b/main.go @@ -4,14 +4,14 @@ package main // github.com/vouch/vouch-proxy import ( + "log" "net/http" "path/filepath" "strconv" "time" - log "github.com/Sirupsen/logrus" - "github.com/gorilla/mux" + "go.uber.org/zap" "github.com/vouch/vouch-proxy/handlers" "github.com/vouch/vouch-proxy/pkg/cfg" @@ -21,7 +21,6 @@ import ( // version and semver get overwritten by build with // go build -i -v -ldflags="-X main.version=$(git describe --always --long) -X main.semver=v$(git semver get)" - var ( version = "undefined" builddt = "undefined" @@ -29,22 +28,31 @@ var ( semver = "undefined" branch = "undefined" staticDir = "/static/" + logger = cfg.Cfg.Logger + fastlog = cfg.Cfg.FastLogger ) -func init() { - // var listen = cfg.Cfg.Listen + ":" + strconv.Itoa(cfg.Cfg.Port) +// fwdToZapWriter allows us to use the zap.Logger as our http.Server ErrorLog +// see https://stackoverflow.com/questions/52294334/net-http-set-custom-logger +type fwdToZapWriter struct { + logger *zap.Logger +} + +func (fw *fwdToZapWriter) Write(p []byte) (n int, err error) { + fw.logger.Error(string(p)) + return len(p), nil } func main() { var listen = cfg.Cfg.Listen + ":" + strconv.Itoa(cfg.Cfg.Port) - log.WithFields(log.Fields{ + logger.Infow("starting "+cfg.Branding.CcName, // "semver": semver, - "version": version, - "buildtime": builddt, - "buildhost": host, - "branch": branch, - "semver": semver, - "listen": listen}).Info("starting " + cfg.Branding.CcName) + "version", version, + "buildtime", builddt, + "buildhost", host, + "branch", branch, + "semver", semver, + "listen", listen) mux := mux.NewRouter() @@ -64,18 +72,18 @@ func main() { healthH := http.HandlerFunc(handlers.HealthcheckHandler) mux.HandleFunc("/healthcheck", timelog.TimeLog(healthH)) - if log.GetLevel() == log.DebugLevel { + if logger.Desugar().Core().Enabled(zap.DebugLevel) { path, err := filepath.Abs(staticDir) if err != nil { - log.Errorf("couldn't find static assets at %s", path) + logger.Errorf("couldn't find static assets at %s", path) } - log.Debugf("serving static files from %s", path) + logger.Debugf("serving static files from %s", path) } // https://golangcode.com/serve-static-assets-using-the-mux-router/ mux.PathPrefix(staticDir).Handler(http.StripPrefix(staticDir, (http.FileServer(http.Dir("." + staticDir))))) if cfg.Cfg.WebApp { - log.Info("enabling websocket") + logger.Info("enabling websocket") tran.ExplicitInit() mux.Handle("/ws", tran.WS) } @@ -90,9 +98,7 @@ func main() { // Good practice: enforce timeouts for servers you create! WriteTimeout: 15 * time.Second, ReadTimeout: 15 * time.Second, - /// logrus has an example of using ErrorLog but it doesn't apply to this MUX implimentation - // https://github.com/sirupsen/logrus#logger-as-an-iowriter - // ErrorLog: log.New(w, "", 0), + ErrorLog: log.New(&fwdToZapWriter{fastlog}, "", 0), } log.Fatal(srv.ListenAndServe()) diff --git a/pkg/cfg/cfg.go b/pkg/cfg/cfg.go index 797a1771..4b480d06 100644 --- a/pkg/cfg/cfg.go +++ b/pkg/cfg/cfg.go @@ -10,17 +10,20 @@ import ( "strconv" "strings" - log "github.com/Sirupsen/logrus" "golang.org/x/oauth2" "golang.org/x/oauth2/github" "golang.org/x/oauth2/google" "github.com/spf13/viper" securerandom "github.com/theckman/go-securerandom" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) // config vouch jwt cookie configuration type config struct { + Logger *zap.SugaredLogger + FastLogger *zap.Logger LogLevel string `mapstructure:"logLevel"` Listen string `mapstructure:"listen"` Port int `mapstructure:"port"` @@ -124,6 +127,8 @@ var ( secretFile = os.Getenv("VOUCH_ROOT") + "config/secret" cmdLineConfig *string + + log *zap.SugaredLogger ) const ( @@ -141,17 +146,36 @@ func init() { help := flag.Bool("help", false, "show usage") cmdLineConfig = flag.String("config", "", "specify alternate .yml file as command line arg") flag.Parse() + + atom := zap.NewAtomicLevel() + // logger, _ := zap.NewProduction() + // encoderCfg := zap.NewDevelopmentEncoderConfig() + encoderCfg := zap.NewProductionEncoderConfig() + // encoderCfg.TimeKey = "" + + logger := zap.New(zapcore.NewCore( + zapcore.NewJSONEncoder(encoderCfg), + zapcore.Lock(os.Stdout), + atom, + )) + + defer logger.Sync() // flushes buffer, if any + log = logger.Sugar() + Cfg.Logger = log + Cfg.FastLogger = log.Desugar() + ParseConfig() + + if *ll == "debug" || Cfg.LogLevel == "debug" { + atom.SetLevel(zap.DebugLevel) + log.Debug("logLevel set to debug") + } + if *help { flag.PrintDefaults() os.Exit(1) } - if *ll == "debug" { - log.SetLevel(log.DebugLevel) - log.Debug("logLevel set to debug") - } - setDefaults() if *port != -1 { @@ -169,7 +193,7 @@ func init() { log.Fatal(errors.New(listen + " is not available (is " + Branding.CcName + " already running?)")) } - log.Debug(viper.AllSettings()) + log.Debugw("viper settings", viper.AllSettings()) } // ParseConfig parse the config file diff --git a/pkg/cfg/cfg_test.go b/pkg/cfg/cfg_test.go index b4a8aba7..d9d17c71 100644 --- a/pkg/cfg/cfg_test.go +++ b/pkg/cfg/cfg_test.go @@ -3,8 +3,6 @@ package cfg import ( "testing" // "github.com/vouch/vouch-proxy/pkg/structs" - // log "github.com/Sirupsen/logrus" - log "github.com/Sirupsen/logrus" "github.com/stretchr/testify/assert" ) diff --git a/pkg/cookie/cookie.go b/pkg/cookie/cookie.go index f6a140b3..9a63f1ae 100644 --- a/pkg/cookie/cookie.go +++ b/pkg/cookie/cookie.go @@ -5,12 +5,12 @@ import ( "net/http" // "github.com/vouch/vouch-proxy/pkg/structs" - log "github.com/Sirupsen/logrus" "github.com/vouch/vouch-proxy/pkg/cfg" "github.com/vouch/vouch-proxy/pkg/domains" ) var defaultMaxAge = cfg.Cfg.JWT.MaxAge * 60 +var log = cfg.Cfg.Logger // SetCookie http func SetCookie(w http.ResponseWriter, r *http.Request, val string) { @@ -50,10 +50,10 @@ func Cookie(r *http.Request) (string, error) { return "", errors.New("Cookie token empty") } - log.WithFields(log.Fields{ - "cookieName": cfg.Cfg.Cookie.Name, - "cookieValue": cookie.Value, - }).Debug("cookie") + log.Debugw("cookie", + "cookieName", cfg.Cfg.Cookie.Name, + "cookieValue", cookie.Value, + ) return cookie.Value, err } diff --git a/pkg/cors/cors.go b/pkg/cors/cors.go index 0baa19bd..e4eea967 100644 --- a/pkg/cors/cors.go +++ b/pkg/cors/cors.go @@ -3,9 +3,11 @@ package cors import ( "net/http" - log "github.com/Sirupsen/logrus" + "github.com/vouch/vouch-proxy/pkg/cfg" ) +var log = cfg.Cfg.Logger + // AllowAll is middle ware to set Access-Control-Allow-Origin: * func AllowAll(nextHandler http.Handler) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { diff --git a/pkg/domains/domains.go b/pkg/domains/domains.go index d90fa88d..e28c9b54 100644 --- a/pkg/domains/domains.go +++ b/pkg/domains/domains.go @@ -4,11 +4,11 @@ import ( "sort" "strings" - log "github.com/Sirupsen/logrus" "github.com/vouch/vouch-proxy/pkg/cfg" ) var domains = cfg.Cfg.Domains +var log = cfg.Cfg.Logger func init() { sort.Sort(ByLengthDesc(domains)) diff --git a/pkg/jwtmanager/jwtmanager.go b/pkg/jwtmanager/jwtmanager.go index f6f7558e..86035465 100644 --- a/pkg/jwtmanager/jwtmanager.go +++ b/pkg/jwtmanager/jwtmanager.go @@ -10,7 +10,6 @@ import ( "strings" "time" - log "github.com/Sirupsen/logrus" "github.com/vouch/vouch-proxy/pkg/cfg" "github.com/vouch/vouch-proxy/pkg/structs" @@ -31,6 +30,7 @@ var StandardClaims jwt.StandardClaims // Sites just testing var Sites []string +var log = cfg.Cfg.Logger func init() { StandardClaims = jwt.StandardClaims{ diff --git a/pkg/jwtmanager/jwtmanager_test.go b/pkg/jwtmanager/jwtmanager_test.go index 95a3d873..d4a07d59 100644 --- a/pkg/jwtmanager/jwtmanager_test.go +++ b/pkg/jwtmanager/jwtmanager_test.go @@ -6,8 +6,6 @@ import ( "github.com/vouch/vouch-proxy/pkg/cfg" "github.com/vouch/vouch-proxy/pkg/structs" - // log "github.com/Sirupsen/logrus" - log "github.com/Sirupsen/logrus" "github.com/stretchr/testify/assert" ) @@ -18,6 +16,8 @@ var ( } lc VouchClaims + + log = cfg.Cfg.Logger ) func init() { diff --git a/pkg/model/model.go b/pkg/model/model.go index e8355448..036e3b12 100644 --- a/pkg/model/model.go +++ b/pkg/model/model.go @@ -8,7 +8,6 @@ import ( "os" "time" - log "github.com/Sirupsen/logrus" "github.com/boltdb/bolt" "github.com/vouch/vouch-proxy/pkg/cfg" ) @@ -30,6 +29,8 @@ var ( userBucket = []byte("users") teamBucket = []byte("teams") siteBucket = []byte("sites") + + log = cfg.Cfg.Logger ) // may want to use encode/gob to store the user record diff --git a/pkg/model/model_test.go b/pkg/model/model_test.go index f875de49..144fd226 100644 --- a/pkg/model/model_test.go +++ b/pkg/model/model_test.go @@ -7,14 +7,14 @@ import ( "os" "testing" - log "github.com/Sirupsen/logrus" - "github.com/stretchr/testify/assert" + "github.com/vouch/vouch-proxy/pkg/cfg" "github.com/vouch/vouch-proxy/pkg/structs" ) var testdb = "/tmp/storage-test.db" +var log = cfg.Cfg.Logger func init() { Db, _ = OpenDB(testdb) diff --git a/pkg/model/site.go b/pkg/model/site.go index 8a4f5f55..6acd191c 100644 --- a/pkg/model/site.go +++ b/pkg/model/site.go @@ -5,7 +5,6 @@ import ( "encoding/gob" "time" - log "github.com/Sirupsen/logrus" "github.com/boltdb/bolt" "github.com/vouch/vouch-proxy/pkg/structs" ) diff --git a/pkg/model/team.go b/pkg/model/team.go index 6bb926c4..8ac7aa5d 100644 --- a/pkg/model/team.go +++ b/pkg/model/team.go @@ -6,7 +6,6 @@ import ( "fmt" "time" - log "github.com/Sirupsen/logrus" "github.com/boltdb/bolt" "github.com/vouch/vouch-proxy/pkg/structs" ) diff --git a/pkg/model/user.go b/pkg/model/user.go index 15f86949..50e5be70 100644 --- a/pkg/model/user.go +++ b/pkg/model/user.go @@ -6,7 +6,6 @@ import ( "fmt" "time" - log "github.com/Sirupsen/logrus" "github.com/boltdb/bolt" "github.com/vouch/vouch-proxy/pkg/structs" ) diff --git a/pkg/response/response.go b/pkg/response/response.go index de744959..40589e1f 100644 --- a/pkg/response/response.go +++ b/pkg/response/response.go @@ -1,12 +1,17 @@ package response -import "net/http" -import log "github.com/Sirupsen/logrus" +import ( + "net/http" + + "github.com/vouch/vouch-proxy/pkg/cfg" +) // we wrap ResponseWriter so that we can store the StatusCode // and then pull it out later for logging // https://play.golang.org/p/wPHaX9DH-Ik +var log = cfg.Cfg.FastLogger + // CaptureWriter extends http.ResponseWriter type CaptureWriter struct { http.ResponseWriter @@ -16,7 +21,7 @@ type CaptureWriter struct { func (w *CaptureWriter) Write(b []byte) (int, error) { if w.StatusCode == 0 { w.StatusCode = 200 - log.Debugf("CaptureWriter.Write set w.StatusCode %d", w.StatusCode) + log.Debug("CaptureWriter.Write set w.StatusCode " + string(w.StatusCode)) } return w.ResponseWriter.Write(b) } @@ -29,7 +34,7 @@ func (w *CaptureWriter) Header() http.Header { // WriteHeader calls http.Writer.WriteHeader(code) func (w *CaptureWriter) WriteHeader(code int) { w.StatusCode = code - log.Debugf("CaptureWriter.WriteHeader set w.StatusCode %d", w.StatusCode) + log.Debug("CaptureWriter.Write set w.StatusCode " + string(w.StatusCode)) w.ResponseWriter.WriteHeader(code) } diff --git a/pkg/structs/structs.go b/pkg/structs/structs.go index af99ff65..627d4cfb 100644 --- a/pkg/structs/structs.go +++ b/pkg/structs/structs.go @@ -26,7 +26,6 @@ func (u *User) PrepareUserData() { // GoogleUser is a retrieved and authentiacted user from Google. // unused! - // TODO: see if these should be pointers to the *User object as per // https://golang.org/doc/effective_go.html#embedding type GoogleUser struct { @@ -47,6 +46,7 @@ func (u *GoogleUser) PrepareUserData() { u.Username = u.Email } +// ADFSUser Active Directory user record type ADFSUser struct { User Sub string `json:"sub"` @@ -77,11 +77,13 @@ func (u *GitHubUser) PrepareUserData() { u.Username = u.Login } +// IndieAuthUser see indieauth.net type IndieAuthUser struct { User URL string `json:"me"` } +// PrepareUserData implement PersonalData interface func (u *IndieAuthUser) PrepareUserData() { u.Username = u.URL } diff --git a/pkg/timelog/timelog.go b/pkg/timelog/timelog.go index 29052f15..0bb3987c 100644 --- a/pkg/timelog/timelog.go +++ b/pkg/timelog/timelog.go @@ -4,36 +4,18 @@ import ( "context" "fmt" "net/http" - "os" - "strconv" "time" + "github.com/vouch/vouch-proxy/pkg/cfg" "github.com/vouch/vouch-proxy/pkg/response" - - log "github.com/Sirupsen/logrus" - isatty "github.com/mattn/go-isatty" ) var ( - useColor = false - green = string([]byte{27, 91, 57, 55, 59, 52, 50, 109}) - white = string([]byte{27, 91, 57, 48, 59, 52, 55, 109}) - yellow = string([]byte{27, 91, 57, 55, 59, 52, 51, 109}) - red = string([]byte{27, 91, 57, 55, 59, 52, 49, 109}) - blue = string([]byte{27, 91, 57, 55, 59, 52, 52, 109}) - magenta = string([]byte{27, 91, 57, 55, 59, 52, 53, 109}) - cyan = string([]byte{27, 91, 57, 55, 59, 52, 54, 109}) - reset = string([]byte{27, 91, 48, 109}) req = int64(0) avgLatency = int64(0) -) -func init() { - if isatty.IsTerminal(os.Stdout.Fd()) { - useColor = true - } - // useColor = false -} + log = cfg.Cfg.Logger +) // TimeLog records how long it takes to process the http request and produce the response (latency) func TimeLog(nextHandler http.Handler) func(http.ResponseWriter, *http.Request) { @@ -57,47 +39,19 @@ func TimeLog(nextHandler http.Handler) func(http.ResponseWriter, *http.Request) path := r.URL.Path host := r.Host referer := r.Header.Get("Referer") - clientIP := r.RemoteAddr method := r.Method - log.WithFields(log.Fields{ - "statusCode": statusCode, - "request": req, - "latency": fmt.Sprintf("%10v", time.Duration(latency)), - "avgLatency": fmt.Sprintf("%10v", time.Duration(avgLatency)), - "ipPort": clientIP, - "method": method, - "host": host, - "path": path, - "referer": referer, - }).Infof("|%s| %10v %s", colorStatus(statusCode), time.Duration(latency), path) - - // log.Infof("|%s %3d %s| %d %10v %10v | %s | %s %s %s | %s", - // statusColor, statusCode, reset, - // req, latency, time.Duration(avgLatency), - // clientIP, - // method, host, path, - // referer) - } -} - -func colorForStatus(code int) string { - switch { - case code >= 200 && code < 300: - return green - case code >= 300 && code < 400: - return white - case code >= 400 && code < 500: - return yellow - default: - return red - } -} - -func colorStatus(code int) string { - if !useColor { - return strconv.Itoa(code) + log.Infow(fmt.Sprintf("|%d| %10v %s", statusCode, time.Duration(latency), path), + "statusCode", statusCode, + "request", req, + "latency", time.Duration(latency), + "avgLatency", time.Duration(avgLatency), + "ipPort", clientIP, + "method", method, + "host", host, + "path", path, + "referer", referer, + ) } - return fmt.Sprintf("%s %3d %s", colorForStatus(code), code, reset) } diff --git a/pkg/transciever/client.go b/pkg/transciever/client.go index 6d862a87..b556abba 100644 --- a/pkg/transciever/client.go +++ b/pkg/transciever/client.go @@ -6,10 +6,10 @@ import ( "net/http" "time" + "github.com/vouch/vouch-proxy/pkg/cfg" "github.com/vouch/vouch-proxy/pkg/model" "github.com/vouch/vouch-proxy/pkg/structs" - log "github.com/Sirupsen/logrus" "github.com/mitchellh/mapstructure" "github.com/gorilla/websocket" @@ -19,6 +19,7 @@ import ( // https://github.com/gorilla/websocket/blob/master/examples/chat/client.go var allConns map[*websocket.Conn]bool +var log = cfg.Cfg.Logger const ( // Time allowed to write a message to the peer. @@ -216,7 +217,7 @@ func (c *Client) shipping(t string, v interface{}) { func serveWs(hub *Hub, w http.ResponseWriter, r *http.Request) { conn, err := upgrader.Upgrade(w, r, nil) if err != nil { - log.Println(err) + log.Info(err) return } client := &Client{hub: hub, conn: conn, send: make(chan []byte, 256)} diff --git a/pkg/transciever/transciever.go b/pkg/transciever/transciever.go index 2eb2e3d9..bbeb3735 100644 --- a/pkg/transciever/transciever.go +++ b/pkg/transciever/transciever.go @@ -2,8 +2,6 @@ package transciever import ( "net/http" - - log "github.com/Sirupsen/logrus" ) // WSHandler implements the Handler Interface