Update logging formatting/encoder (#547)

* logging

* update version logging

internal/cmd/version.go

@@ -10,6 +10,7 @@ import (
 	"text/tabwriter"
 
 	"github.com/infrahq/infra/internal"
+	"github.com/infrahq/infra/internal/logging"
 	"golang.org/x/mod/semver"
 )
 
@@ -89,11 +90,11 @@ func checkUpdate(clientVersion, serverVersion string) error {
 	}
 
 	if clientSemVer != "v0.0.0-development" && semver.Compare(latestSemVer, clientSemVer) > 0 {
-		fmt.Fprintf(os.Stderr, "Infra CLI (%s) is out of date. Please update to %s.\n", clientVersion, latestVersion)
+		logging.S.Warnf("Infra CLI (%s) is out of date. Please update to %s.", clientVersion, latestVersion)
 	}
 
 	if serverSemVer != "v0.0.0-development" && semver.IsValid(serverSemVer) && semver.Compare(latestSemVer, serverSemVer) > 0 {
-		fmt.Fprintf(os.Stderr, "Infra (%s) is out of date. Please update to %s.\n", serverVersion, latestVersion)
+		logging.S.Warnf("Infra (%s) is out of date. Please update to %s.", serverVersion, latestVersion)
 	}
 
 	return nil

internal/engine/engine.go

@@ -7,12 +7,12 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"net"
 	"net/http"
 	"net/http/httputil"
 	"net/url"
-	"os"
 	"regexp"
 	"strings"
 	"sync"
@@ -443,7 +443,7 @@ func Run(options *Options) error {
 	tlsServer := &http.Server{
 		Addr:      ":443",
 		TLSConfig: tlsConfig,
-		Handler:   handlers.LoggingHandler(os.Stdout, mux),
+		Handler:   handlers.CustomLoggingHandler(io.Discard, mux, logging.ZapLogFormatter),
 	}
 
 	logging.L.Info("serving on port 443")

internal/kubernetes/kubernetes.go

@@ -19,7 +19,6 @@ import (
 	"github.com/infrahq/infra/internal/logging"
 	"github.com/infrahq/infra/secrets"
 	"github.com/jessevdk/go-flags"
-	"go.uber.org/zap"
 	corev1 "k8s.io/api/core/v1"
 	rbacv1 "k8s.io/api/rbac/v1"
 	k8sErrors "k8s.io/apimachinery/pkg/api/errors"
@@ -180,7 +179,7 @@ func (k *Kubernetes) updateRoleBindings(subjects map[namespaceRole][]rbacv1.Subj
 					if k8sErrors.IsNotFound(err) {
 						// the namespace does not exist
 						// we can proceed in this case, the role mapping is just not applicable to this cluster
-						logging.L.Warn("skipping unapplicable namespace for this cluster: "+rb.Namespace, zap.Error(err))
+						logging.S.Warnf("skipping unapplicable namespace for this cluster: %s %s", rb.Namespace, err.Error())
 						continue
 					}
 

internal/logging/logger.go

@@ -2,29 +2,59 @@
 package logging
 
 import (
+	"io"
+	"os"
+
+	"github.com/gorilla/handlers"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"golang.org/x/term"
 )
 
 var (
 	L *zap.Logger        = zap.L()
 	S *zap.SugaredLogger = zap.S()
 )
 
-func Initialize(level string) (*zap.Logger, error) {
-	config := zap.NewProductionConfig()
+func Initialize(l string) (*zap.Logger, error) {
 	atom := zap.NewAtomicLevel()
-
-	err := atom.UnmarshalText([]byte(level))
-	if err != nil {
+	if err := atom.UnmarshalText([]byte(l)); err != nil {
 		return nil, err
 	}
 
-	config.Level = atom
+	var (
+		encoder zapcore.Encoder
+		writer  zapcore.WriteSyncer
+	)
 
-	logger, err := config.Build()
-	if err != nil {
-		return nil, err
+	if term.IsTerminal(int(os.Stdin.Fd())) {
+		writer = zapcore.Lock(os.Stderr)
+		encoder = zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
+			MessageKey: "message",
+
+			LevelKey:    "level",
+			EncodeLevel: zapcore.CapitalColorLevelEncoder,
+
+			TimeKey:    "time",
+			EncodeTime: zapcore.ISO8601TimeEncoder,
+
+			CallerKey:    "caller",
+			EncodeCaller: zapcore.ShortCallerEncoder,
+		})
+	} else {
+		writer = zapcore.Lock(os.Stdout)
+		encoder = zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())
 	}
 
-	return logger, nil
+	core := zapcore.NewCore(encoder, writer, atom)
+
+	return zap.New(core), nil
+}
+
+func ZapLogFormatter(_ io.Writer, params handlers.LogFormatterParams) {
+	L.Debug("handled request",
+		zap.String("method", params.Request.Method),
+		zap.String("path", params.URL.Path),
+		zap.Int("status", params.StatusCode),
+		zap.Int("size", params.Size))
 }

internal/registry/http.go

@@ -9,9 +9,7 @@ import (
 	"strings"
 	"time"
 
-	"github.com/go-chi/chi/middleware"
 	"github.com/infrahq/infra/internal/logging"
-	"go.uber.org/zap"
 	"gopkg.in/square/go-jose.v2"
 	"gorm.io/gorm"
 )
@@ -59,23 +57,6 @@ func deleteAuthCookie(w http.ResponseWriter) {
 	})
 }
 
-func ZapLoggerHttpMiddleware(next http.Handler) http.HandlerFunc {
-	return func(w http.ResponseWriter, r *http.Request) {
-		ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
-		t1 := time.Now()
-
-		next.ServeHTTP(ww, r)
-
-		logging.L.Info("finished http method call",
-			zap.String("method", r.Method),
-			zap.String("path", r.URL.Path),
-			zap.Int("status", ww.Status()),
-			zap.String("proto", r.Proto),
-			zap.Duration("time_ms", time.Since(t1)),
-		)
-	}
-}
-
 type Http struct {
 	db *gorm.DB
 }

internal/registry/registry.go

@@ -6,6 +6,7 @@ package registry
 import (
 	"errors"
 	"fmt"
+	"io"
 	"io/fs"
 	"io/ioutil"
 	"net/http"
@@ -19,6 +20,7 @@ import (
 	assetfs "github.com/elazarl/go-bindata-assetfs"
 	"github.com/getsentry/sentry-go"
 	sentryhttp "github.com/getsentry/sentry-go/http"
+	"github.com/gorilla/handlers"
 	"github.com/goware/urlx"
 	"github.com/infrahq/infra/internal"
 	"github.com/infrahq/infra/internal/api"
@@ -351,7 +353,7 @@ func (r *Registry) runServer() error {
 
 	plaintextServer := http.Server{
 		Addr:    ":80",
-		Handler: ZapLoggerHttpMiddleware(sentryHandler.Handle(mux)),
+		Handler: handlers.CustomLoggingHandler(io.Discard, sentryHandler.Handle(mux), logging.ZapLogFormatter),
 	}
 
 	go func() {
@@ -374,7 +376,7 @@ func (r *Registry) runServer() error {
 	tlsServer := &http.Server{
 		Addr:      ":443",
 		TLSConfig: tlsConfig,
-		Handler:   ZapLoggerHttpMiddleware(sentryHandler.Handle(mux)),
+		Handler:   handlers.CustomLoggingHandler(io.Discard, sentryHandler.Handle(mux), logging.ZapLogFormatter),
 	}
 
 	if err := tlsServer.ListenAndServeTLS("", ""); err != nil {