MAJOR: log: rework how logging works in dataplaneapi

Added multiple loggers and two log_types: app and access. Access logs
are Apache Common Log formated logs for dataplaneapi, while app logs
are standard application logging. Using configuration file, now
you can configure multiple logging targets, e.g. logging to multiple
files, or syslogs all with separate configurations. Leaving old
options as deprecated as they will be used only if no log_targets
are configured in the configuration file.

Author: mjuraga

adapters/adapters.go

@@ -17,26 +17,17 @@ package adapters
 
 import (
 	"fmt"
-	"io"
-	"math/rand"
 	"net/http"
 	"runtime"
 	"strconv"
 	"strings"
-	"time"
 
-	"github.com/docker/go-units"
 	clientnative "github.com/haproxytech/client-native/v2"
 	"github.com/haproxytech/client-native/v2/models"
-	apachelog "github.com/lestrrat-go/apache-logformat"
-	"github.com/oklog/ulid/v2"
-	"github.com/sirupsen/logrus"
+	"github.com/haproxytech/dataplaneapi/log"
 )
 
-var (
-	apacheLogWritter *io.PipeWriter
-	configVersion    string
-)
+var configVersion string
 
 func ConfigVersion() string {
 	return configVersion
@@ -45,47 +36,6 @@ func ConfigVersion() string {
 // Adapter is just a wrapper over http handler function
 type Adapter func(http.Handler) http.Handler
 
-type statusResponseWriter struct {
-	http.ResponseWriter
-	status int
-	length int
-}
-
-func (srw *statusResponseWriter) WriteHeader(s int) {
-	srw.status = s
-	srw.ResponseWriter.WriteHeader(s)
-}
-
-func (srw *statusResponseWriter) Write(b []byte) (int, error) {
-	if srw.status == 0 {
-		// The status will be StatusOK if WriteHeader has not been called yet
-		srw.status = 200
-		srw.ResponseWriter.WriteHeader(srw.Status())
-	}
-	size, err := srw.ResponseWriter.Write(b)
-	srw.length = size
-	return size, err
-}
-
-func (srw *statusResponseWriter) Header() http.Header {
-	return srw.ResponseWriter.Header()
-}
-
-func (srw *statusResponseWriter) Status() int {
-	return srw.status
-}
-
-func (srw *statusResponseWriter) Length() int {
-	return srw.length
-}
-
-func newStatusResponseWriter(rw http.ResponseWriter) *statusResponseWriter {
-	nsrw := &statusResponseWriter{
-		ResponseWriter: rw,
-	}
-	return nsrw
-}
-
 type frame struct {
 	File string
 	Line int
@@ -133,15 +83,16 @@ func stripPackage(n string) string {
 }
 
 // RecoverMiddleware used for recovering from panic, logs the panic to given logger and returns 500
-func RecoverMiddleware(entry logrus.FieldLogger) func(h http.Handler) http.Handler {
+func RecoverMiddleware(logger *log.Logger) func(h http.Handler) http.Handler {
 	return func(h http.Handler) http.Handler {
 		fn := func(w http.ResponseWriter, r *http.Request) {
 			defer func() {
 				if err := recover(); err != nil {
 					frames := callers()
 
-					entry := entry.WithField("stack_trace", frames.String())
-					entry.Error(fmt.Sprintf("Panic %v", err))
+					fields := make(map[string]interface{})
+					fields["stack_trace"] = frames.String()
+					logger.WithFieldsf(fields, log.ErrorLevel, "Panic %v", err)
 
 					w.WriteHeader(http.StatusInternalServerError)
 
@@ -167,70 +118,13 @@ func RecoverMiddleware(entry logrus.FieldLogger) func(h http.Handler) http.Handl
 	}
 }
 
-func UniqueIDMiddleware(entry *logrus.Entry) Adapter {
-	return func(h http.Handler) http.Handler {
-		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			reqID := r.Header.Get("X-Request-Id")
-			if len(reqID) == 0 {
-				t := time.Now()
-				// we need performance and math/rand does the trick, although it's "unsafe":
-				// speed is absolutely required here since we're going to generate an ULID for each request
-				// that doesn't contain a prefilled X-Request-Id header.
-				entropy := ulid.Monotonic(rand.New(rand.NewSource(t.UnixNano())), 0) // nolint:gosec
-				reqID = ulid.MustNew(ulid.Timestamp(t), entropy).String()
-			}
-			*entry = *entry.WithField("request_id", reqID)
-
-			h.ServeHTTP(w, r)
-		})
-	}
-}
-
-func ApacheLogMiddleware(entry *logrus.Entry, format *apachelog.ApacheLog) Adapter {
+func ApacheLogMiddleware(logger *log.ACLLogger) Adapter {
 	return func(h http.Handler) http.Handler {
-		if apacheLogWritter != nil {
-			apacheLogWritter.Close()
-		}
-		apacheLogWritter = entry.Logger.Writer()
-		return format.Wrap(h, apacheLogWritter)
+		apacheLogWritter := logger.Writer()
+		return logger.ApacheLog.Wrap(h, apacheLogWritter)
 	}
 }
 
-// LoggingMiddleware logs before and after the response to given logger
-func LoggingMiddleware(entry *logrus.Entry) Adapter {
-	return func(h http.Handler) http.Handler {
-		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			start := time.Now()
-			logBefore(entry, r)
-			res := newStatusResponseWriter(w)
-			defer logAfter(entry, res, start)
-			h.ServeHTTP(res, r)
-		})
-	}
-}
-
-func logBefore(entry *logrus.Entry, req *http.Request) {
-	entry.WithFields(logrus.Fields{
-		"request": req.RequestURI,
-		"method":  req.Method,
-		"remote": func() (remote string) {
-			remote = req.RemoteAddr
-			if realIP := req.Header.Get("X-Real-IP"); realIP != "" {
-				remote = realIP
-			}
-			return
-		}(),
-	}).Info("started handling request")
-}
-
-func logAfter(entry *logrus.Entry, res *statusResponseWriter, start time.Time) {
-	entry.WithFields(logrus.Fields{
-		"status": res.Status(),
-		"length": units.HumanSize(float64(res.Length())),
-		"took":   time.Since(start),
-	}).Info("completed handling request")
-}
-
 func ConfigVersionMiddleware(client *clientnative.HAProxyClient) Adapter {
 	return func(h http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {

cmd/dataplaneapi/main.go

@@ -17,23 +17,20 @@ package main
 
 import (
 	"fmt"
-	"io/ioutil"
 	"os"
 	"path"
-	"path/filepath"
 	"syscall"
 
 	loads "github.com/go-openapi/loads"
 	"github.com/go-openapi/runtime"
 	"github.com/go-openapi/runtime/security"
 	flags "github.com/jessevdk/go-flags"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/haproxytech/client-native/v2/storage"
 	"github.com/haproxytech/dataplaneapi"
 	"github.com/haproxytech/dataplaneapi/configuration"
+	"github.com/haproxytech/dataplaneapi/log"
 	"github.com/haproxytech/dataplaneapi/operations"
-	"github.com/haproxytech/dataplaneapi/syslog"
 )
 
 // GitRepo ...
@@ -51,14 +48,6 @@ var GitDirty = ".dirty"
 // BuildTime ...
 var BuildTime = ""
 
-func init() {
-	log.SetFormatter(&log.TextFormatter{
-		FullTimestamp: true,
-		DisableColors: true,
-	})
-	log.SetOutput(os.Stdout)
-}
-
 var cliOptions struct {
 	Version bool `short:"v" long:"version" description:"Version and build information"`
 }
@@ -76,7 +65,8 @@ func main() {
 func startServer(cfg *configuration.Configuration) (reload configuration.AtomicBool) {
 	swaggerSpec, err := loads.Embedded(dataplaneapi.SwaggerJSON, dataplaneapi.FlatSwaggerJSON)
 	if err != nil {
-		log.Fatalln(err)
+		fmt.Println(err)
+		os.Exit(1)
 	}
 
 	dataplaneapi.BuildTime = BuildTime
@@ -93,21 +83,24 @@ func startServer(cfg *configuration.Configuration) (reload configuration.AtomicB
 	for _, optsGroup := range api.CommandLineOptionsGroups {
 		_, err = parser.AddGroup(optsGroup.ShortDescription, optsGroup.LongDescription, optsGroup.Options)
 		if err != nil {
-			log.Fatalln(err)
+			fmt.Println(err)
+			os.Exit(1)
 		}
 	}
 
 	_, err = parser.AddGroup("Show version", "Show build and version information", &cliOptions)
 	if err != nil {
-		log.Fatalln(err)
+		fmt.Println(err)
+		os.Exit(1)
 	}
 
 	if _, err = parser.Parse(); err != nil {
 		if fe, ok := err.(*flags.Error); ok {
 			if fe.Type == flags.ErrHelp {
 				os.Exit(0)
 			} else {
-				log.Fatalln(err)
+				fmt.Println(err)
+				os.Exit(1)
 			}
 		}
 	}
@@ -121,26 +114,30 @@ func startServer(cfg *configuration.Configuration) (reload configuration.AtomicB
 
 	err = cfg.Load()
 	if err != nil {
-		log.Fatalln(err)
+		fmt.Println(err)
+		os.Exit(1)
 	}
 
 	if cfg.HAProxy.UID != 0 {
 		if err = syscall.Setuid(cfg.HAProxy.UID); err != nil {
-			log.Fatalln("set uid:", err)
+			fmt.Println("set uid:", err)
+			os.Exit(1)
 		}
 	}
 
 	if cfg.HAProxy.GID != 0 {
 		if err = syscall.Setgid(cfg.HAProxy.GID); err != nil {
-			log.Fatalln("set gid:", err)
+			fmt.Println("set gid:", err)
+			os.Exit(1)
 		}
 	}
 
 	// incorporate changes from file to global settings
 	dataplaneapi.SyncWithFileSettings(server, cfg)
 	err = cfg.LoadRuntimeVars(dataplaneapi.SwaggerJSON, server.Host, server.Port)
 	if err != nil {
-		log.Fatalln(err)
+		fmt.Println(err)
+		os.Exit(1)
 	}
 
 	configuration.HandlePIDFile(cfg.HAProxy)
@@ -172,15 +169,18 @@ func startServer(cfg *configuration.Configuration) (reload configuration.AtomicB
 		}
 	}
 
-	setupLogging(cfg)
+	if err = log.InitWithConfiguration(cfg.LogTargets, cfg.Logging, cfg.Syslog); err != nil {
+		fmt.Println(err)
+		os.Exit(1)
+	}
 
 	log.Infof("HAProxy Data Plane API %s %s%s", GitTag, GitCommit, GitDirty)
 	log.Infof("Build from: %s", GitRepo)
 	log.Infof("Build date: %s", BuildTime)
 
 	err = cfg.Save()
 	if err != nil {
-		log.Fatalln(err)
+		log.Fatalf("Error saving configuration: %s", err.Error())
 	}
 
 	// Applies when the Authorization header is set with the Basic scheme
@@ -204,7 +204,7 @@ func startServer(cfg *configuration.Configuration) (reload configuration.AtomicB
 		dataplaneapi.ContextHandler.Cancel()
 		err := server.Shutdown()
 		if err != nil {
-			log.Fatalln(err)
+			log.Fatalf("Error reloading HAProxy Data Plane API: %s", err.Error())
 		}
 	}()
 
@@ -214,7 +214,7 @@ func startServer(cfg *configuration.Configuration) (reload configuration.AtomicB
 			log.Info("HAProxy Data Plane API shutting down")
 			err := server.Shutdown()
 			if err != nil {
-				log.Fatalln(err)
+				log.Fatalf("Error shutting down HAProxy Data Plane API: %s", err.Error())
 			}
 			os.Exit(0)
 		case <-dataplaneapi.ContextHandler.Context().Done():
@@ -224,74 +224,10 @@ func startServer(cfg *configuration.Configuration) (reload configuration.AtomicB
 
 	server.ConfigureAPI()
 	if err := server.Serve(); err != nil {
-		log.Fatalln(err)
+		log.Fatalf("Error running HAProxy Data Plane API: %s", err.Error())
 	}
 
 	defer server.Shutdown() // nolint:errcheck
 
 	return reload
 }
-
-func setupLogging(cfg *configuration.Configuration) {
-	appLogger := log.StandardLogger()
-	configureLogger(appLogger, cfg.Logging, func(opts configuration.SyslogOptions) configuration.SyslogOptions {
-		opts.SyslogMsgID = "app"
-		return opts
-	}(cfg.Syslog))
-
-	accLogger := log.StandardLogger()
-	configureLogger(accLogger, cfg.Logging, func(opts configuration.SyslogOptions) configuration.SyslogOptions {
-		opts.SyslogMsgID = "accesslog"
-		return opts
-	}(cfg.Syslog))
-
-	dataplaneapi.AppLogger = appLogger
-	dataplaneapi.AccLogger = accLogger
-}
-
-func configureLogger(logger *log.Logger, loggingOptions configuration.LoggingOptions, syslogOptions configuration.SyslogOptions) {
-	switch loggingOptions.LogFormat {
-	case "text":
-		logger.SetFormatter(&log.TextFormatter{
-			FullTimestamp: true,
-			DisableColors: true,
-		})
-	case "JSON":
-		logger.SetFormatter(&log.JSONFormatter{})
-	}
-
-	switch loggingOptions.LogTo {
-	case "stdout":
-		logger.SetOutput(os.Stdout)
-	case "file":
-		dir := filepath.Dir(loggingOptions.LogFile)
-		if err := os.MkdirAll(dir, os.ModePerm); err != nil {
-			log.Warning("Error opening log file, no logging implemented: " + err.Error())
-		}
-		//nolint:govet
-		logFile, err := os.OpenFile(loggingOptions.LogFile, os.O_APPEND|os.O_CREATE|os.O_RDWR, 0666)
-		if err != nil {
-			log.Warning("Error opening log file, no logging implemented: " + err.Error())
-		}
-		log.SetOutput(logFile)
-	case "syslog":
-		logger.SetOutput(ioutil.Discard)
-		hook, err := syslog.NewRFC5424Hook(syslogOptions)
-		if err != nil {
-			log.Warningf("Error configuring Syslog logging: %s", err.Error())
-			break
-		}
-		logger.AddHook(hook)
-	}
-
-	switch loggingOptions.LogLevel {
-	case "debug":
-		logger.SetLevel(log.DebugLevel)
-	case "info":
-		logger.SetLevel(log.InfoLevel)
-	case "warning":
-		logger.SetLevel(log.WarnLevel)
-	case "error":
-		logger.SetLevel(log.ErrorLevel)
-	}
-}