Enable access logs, if configured

api/proxy.go

@@ -3,7 +3,7 @@ package api
 import (
 	"github.com/labstack/echo/v4"
 	"github.com/labstack/echo/v4/middleware"
-	"log"
+	"github.com/rs/zerolog"
 	"net/http"
 	"net/url"
 	"regexp"
@@ -64,7 +64,7 @@ var allowedProxyRoutes = []proxyRoute{
 
 // ConfigureProxy configures the proxy middleware for the given Nuts node address.
 // It allows the web application to call a curated list of endpoints on the Nuts node.
-func ConfigureProxy(e *echo.Echo, nodeAddress *url.URL) {
+func ConfigureProxy(logger zerolog.Logger, e *echo.Echo, nodeAddress *url.URL) {
 	e.Use(middleware.ProxyWithConfig(middleware.ProxyConfig{
 		Balancer: middleware.NewRoundRobinBalancer([]*middleware.ProxyTarget{
 			{
@@ -84,7 +84,7 @@ func ConfigureProxy(e *echo.Echo, nodeAddress *url.URL) {
 			proxyURL = "/" + strings.TrimLeft(proxyURL, "/")
 			for _, route := range allowedProxyRoutes {
 				if c.Request().Method == route.method && route.compiledPath.MatchString(proxyURL) {
-					log.Printf("proxying %s %s", c.Request().Method, proxyURL)
+					logger.Info().Msgf("proxying %s %s", c.Request().Method, proxyURL)
 					return false
 				}
 			}

config.go

@@ -10,7 +10,6 @@ import (
 	"errors"
 	"fmt"
 	"golang.org/x/crypto/ssh"
-	"io"
 	"log"
 	"os"
 	"strings"
@@ -34,13 +33,15 @@ func defaultConfig() Config {
 		Node: Node{
 			Address: "http://localhost:8081",
 		},
+		AccessLogs: true,
 	}
 }
 
 type Config struct {
-	HTTPPort int  `koanf:"port"`
-	Node     Node `koanf:"node"`
-	apiKey   crypto.Signer
+	HTTPPort   int  `koanf:"port"`
+	Node       Node `koanf:"node"`
+	AccessLogs bool `koanf:"accesslogs"`
+	apiKey     crypto.Signer
 }
 
 type Node struct {
@@ -66,19 +67,9 @@ func generateSessionKey() (*ecdsa.PrivateKey, error) {
 	return key, nil
 }
 
-func (c Config) Print(writer io.Writer) error {
-	if _, err := fmt.Fprintln(writer, "========== CONFIG: =========="); err != nil {
-		return err
-	}
-	var pr Config = c
-	data, _ := json.MarshalIndent(pr, "", "  ")
-	if _, err := fmt.Println(writer, string(data)); err != nil {
-		return err
-	}
-	if _, err := fmt.Fprintln(writer, "========= END CONFIG ========="); err != nil {
-		return err
-	}
-	return nil
+func (c Config) Print() {
+	data, _ := json.Marshal(c)
+	logger.Info().Msgf("Config: %s", string(data))
 }
 
 func loadConfig() Config {
@@ -90,12 +81,12 @@ func loadConfig() Config {
 	configFilePath := resolveConfigFile(flagset)
 	// Check if the file exists
 	if _, err := os.Stat(configFilePath); err == nil {
-		log.Printf("Loading config from file: %s", configFilePath)
+		logger.Info().Msgf("Loading config from file: %s", configFilePath)
 		if err := k.Load(file.Provider(configFilePath), yaml.Parser()); err != nil {
-			log.Fatalf("error while loading config from file: %v", err)
+			logger.Fatal().Msgf("error while loading config from file: %v", err)
 		}
 	} else {
-		log.Printf("Using default config because no file was found at: %s", configFilePath)
+		logger.Info().Msgf("Using default config because no file was found at: %s", configFilePath)
 	}
 
 	// load env flags, can't return error

go.mod

@@ -37,6 +37,7 @@ require (
 	github.com/multiformats/go-base36 v0.1.0 // indirect
 	github.com/multiformats/go-multibase v0.2.0 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
+	github.com/rs/zerolog v1.33.0 // indirect
 	github.com/segmentio/asm v1.2.0 // indirect
 	github.com/shengdoushi/base58 v1.0.0 // indirect
 	github.com/valyala/bytebufferpool v1.0.0 // indirect

go.sum

@@ -36,6 +36,7 @@ github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGX
 github.com/cncf/udpa/go v0.0.0-20201120205902-5459f2c99403/go.mod h1:WmhPx2Nbnhtbo57+VJT5O0JRkEi1Wbu0z5j0R8u5Hbk=
 github.com/coreos/go-semver v0.3.0/go.mod h1:nnelYz7RCh+5ahJtPPxZlU+153eP4D4r3EedlOD2RNk=
 github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -195,6 +196,7 @@ github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcME
 github.com/mattn/go-isatty v0.0.11/go.mod h1:PhnuNfih5lzO57/f3n+odYbM4JtupLOxQOAqxQCu2WE=
 github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
 github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
 github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
@@ -266,6 +268,9 @@ github.com/prometheus/procfs v0.1.3/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4O
 github.com/prometheus/procfs v0.6.0/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1xBZuNvfVA=
 github.com/rhnvrm/simples3 v0.6.1/go.mod h1:Y+3vYm2V7Y4VijFoJHHTrja6OgPrJ2cBti8dPGkC3sA=
 github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8=
+github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts=
 github.com/ryanuber/columnize v2.1.0+incompatible/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts=
 github.com/ryanuber/go-glob v1.0.0/go.mod h1:807d1WSdnB0XRJzKNil9Om6lcp/3a0v4qIHxIXzX/Yc=
@@ -403,6 +408,7 @@ golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/sys v0.16.0 h1:xWw16ngr6ZMtmxDyKyIgsE93KNKz5HKmMa3b8ALHidU=
 golang.org/x/sys v0.16.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=

main.go

@@ -8,13 +8,15 @@ import (
 	"errors"
 	"fmt"
 	"github.com/google/uuid"
+	"github.com/labstack/echo/v4/middleware"
 	"github.com/lestrrat-go/jwx/jwk"
 	"github.com/lestrrat-go/jwx/jwt"
 	"github.com/nuts-foundation/nuts-admin/discovery"
 	"github.com/nuts-foundation/nuts-admin/identity"
 	"github.com/nuts-foundation/nuts-admin/issuer"
 	"github.com/nuts-foundation/nuts-admin/nuts/vcr"
 	"github.com/nuts-foundation/nuts-admin/nuts/vdr"
+	"github.com/rs/zerolog"
 	"io/fs"
 	"log"
 	"net/http"
@@ -32,13 +34,14 @@ const assetPath = "web/dist"
 //go:embed web/dist/*
 var embeddedFiles embed.FS
 
+var logger zerolog.Logger
+
 func getFileSystem(useFS bool) http.FileSystem {
 	if useFS {
-		log.Print("using live mode")
+		logger.Info().Msg("using live mode")
 		return http.FS(os.DirFS(assetPath))
 	}
-
-	log.Print("using embed mode")
+	logger.Debug().Msg("using embed mode")
 	fsys, err := fs.Sub(embeddedFiles, assetPath)
 	if err != nil {
 		panic(err)
@@ -48,12 +51,20 @@ func getFileSystem(useFS bool) http.FileSystem {
 }
 
 func main() {
+	logger = zerolog.New(log.Writer()).With().Timestamp().Logger()
 	config := loadConfig()
-	config.Print(log.Writer())
+	config.Print()
 
 	e := echo.New()
 	e.HideBanner = true
 	e.HTTPErrorHandler = httpErrorHandler
+	e.HideBanner = true
+	e.HidePort = true
+	if config.AccessLogs {
+		e.Use(accessLoggerMiddleware(func(c echo.Context) bool {
+			return c.Request().URL.Path == "/status"
+		}, logger))
+	}
 
 	nodeAddress, err := url.Parse(config.Node.Address)
 	if err != nil {
@@ -92,7 +103,7 @@ func main() {
 	}
 
 	api.RegisterHandlers(e, apiWrapper)
-	api.ConfigureProxy(e, nodeAddress)
+	api.ConfigureProxy(logger, e, nodeAddress)
 
 	// Setup asset serving:
 	// Check if we use live mode from the file system or using embedded files
@@ -216,3 +227,31 @@ func ecAlgUsingPublicKey(key ecdsa.PublicKey) (alg jwa.SignatureAlgorithm, err e
 	}
 	return
 }
+
+// accessLoggerMiddleware returns middleware that logs metadata of HTTP requests.
+// Should be added as the outer middleware to catch all errors and potential status rewrites
+func accessLoggerMiddleware(skipper middleware.Skipper, logger zerolog.Logger) echo.MiddlewareFunc {
+	return middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
+		Skipper:     skipper,
+		LogURI:      true,
+		LogStatus:   true,
+		LogMethod:   true,
+		LogRemoteIP: true,
+		LogError:    true,
+		LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error {
+			event := logger.Info().Fields(map[string]interface{}{
+				"remote_ip": values.RemoteIP,
+				"method":    values.Method,
+				"uri":       values.URI,
+				"status":    values.Status,
+			})
+			if logger.GetLevel() >= zerolog.DebugLevel {
+				event.Fields(map[string]interface{}{
+					"headers": values.Headers,
+				})
+			}
+			event.Msg("HTTP request")
+			return nil
+		},
+	})
+}