fix #88 replace logrus with zap

vouch · Apr 2, 2019 · f200ff9 · f200ff9
1 parent 29d3349
commit f200ff9
Show file tree

Hide file tree

Showing 19 changed files with 121 additions and 129 deletions.
diff --git 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
@@ -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,30 +21,38 @@ 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"
 	host      = "undefined"
 	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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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() {