Structured logging

Makefile

@@ -1,3 +1,4 @@
 .PHONY: build
 build:
-	go build -ldflags "-s -w -X 'github.com/friendsofgo/killgrave/internal/app/cmd._version=`git rev-parse --abbrev-ref HEAD`-`git rev-parse --short HEAD`'" -o bin/killgrave cmd/killgrave/main.go
+	go build -ldflags "-s -w -X 'github.com/friendsofgo/killgrave/internal/app/cmd._version=`git rev-parse --abbrev-ref HEAD`-`git rev-parse --short HEAD`'" -o bin/killgrave cmd/killgrave/main.go
+

cmd/killgrave/main.go

@@ -1,7 +1,7 @@
 package main
 
 import (
-	"log"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/friendsofgo/killgrave/internal/app"
 )

go.mod

@@ -18,9 +18,11 @@ require (
 	github.com/inconshreveable/mousetrap v1.1.0 // indirect
 	github.com/kr/pretty v0.3.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
+	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb // indirect
 	github.com/xeipuuv/gojsonreference v0.0.0-20180127040603-bd5ef7bd5415 // indirect
+	golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8 // indirect
 	gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

go.sum

@@ -23,12 +23,15 @@ github.com/radovskyb/watcher v1.0.7/go.mod h1:78okwvY5wPdzcb1UYnip1pvrZNIVEIh/Cm
 github.com/rogpeppe/go-internal v1.9.0 h1:73kH8U+JUqXU8lRuOHeVHaa/SZPifC7BkcraZVejAe8=
 github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs=
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
+github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
+github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/spf13/cobra v1.8.1 h1:e5/vxKd/rZsfSJMUX1agtjeTDf+qv1/JdBF8gg5k9ZM=
 github.com/spf13/cobra v1.8.1/go.mod h1:wHxEcudfqmLYa8iTfL+OuZPbBZkmvliBWKIezN3kD9Y=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg=
 github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY=
 github.com/xeipuuv/gojsonpointer v0.0.0-20180127040702-4e3ac2762d5f/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU=
@@ -38,10 +41,13 @@ github.com/xeipuuv/gojsonreference v0.0.0-20180127040603-bd5ef7bd5415 h1:EzJWgHo
 github.com/xeipuuv/gojsonreference v0.0.0-20180127040603-bd5ef7bd5415/go.mod h1:GwrjFmJcFw6At/Gs6z4yjiIwzuJ1/+UwLxMQDVQXShQ=
 github.com/xeipuuv/gojsonschema v1.2.0 h1:LhYJRs+L4fBtjZUfuSZIKGeVu0QRy8e5Xi7D17UxZ74=
 github.com/xeipuuv/gojsonschema v1.2.0/go.mod h1:anYRn/JVcOK2ZgGU+IjEV4nwlhoK5sQluxsYJ78Id3Y=
+golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8 h1:0A+M6Uqn+Eje4kHMK80dtF3JCXC4ykBgQG4Fe06QRhQ=
+golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 h1:YR8cESwS4TdDjEe65xsg0ogRM/Nc3DYOhEAlW+xobZo=
 gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY=
 gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ=
+gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
 gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

internal/app/cmd/cmd.go

@@ -3,7 +3,6 @@ package cmd
 import (
 	"errors"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 	"os/signal"
@@ -14,6 +13,7 @@ import (
 	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
 	"github.com/radovskyb/watcher"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 )
 
@@ -26,6 +26,7 @@ const (
 	_defaultPort          = 3000
 	_defaultProxyMode     = killgrave.ProxyNone
 	_defaultStrictSlash   = true
+	_defaultLogLevel      = "info"
 
 	_impostersFlag = "imposters"
 	_configFlag    = "config"
@@ -35,6 +36,7 @@ const (
 	_secureFlag    = "secure"
 	_proxyModeFlag = "proxy-mode"
 	_proxyURLFlag  = "proxy-url"
+	_loglevelFlag  = "log-level"
 )
 
 var (
@@ -77,6 +79,7 @@ func NewKillgraveCmd() *cobra.Command {
 	rootCmd.Flags().BoolP(_secureFlag, "s", false, "Run mock server using TLS (https)")
 	rootCmd.Flags().StringP(_proxyModeFlag, "m", _defaultProxyMode.String(), "Proxy mode, the options are all, missing or none")
 	rootCmd.Flags().StringP(_proxyURLFlag, "u", "", "The url where the proxy will redirect to")
+	rootCmd.Flags().String(_loglevelFlag, _defaultLogLevel, "The log level to output")
 
 	rootCmd.SetVersionTemplate("Killgrave version: {{.Version}}\n")
 
@@ -87,6 +90,8 @@ func runHTTP(cmd *cobra.Command, cfg killgrave.Config) error {
 	done := make(chan os.Signal, 1)
 	defer close(done)
 
+	log.SetLevel(cfg.Log.Level)
+
 	signal.Notify(done, syscall.SIGINT, syscall.SIGTERM)
 
 	srv := runServer(cfg)
@@ -190,7 +195,16 @@ func prepareConfig(cmd *cobra.Command) (killgrave.Config, error) {
 		return killgrave.Config{}, err
 	}
 
-	return cfg, configureProxyMode(cmd, &cfg)
+	if err := configureProxyMode(cmd, &cfg); err != nil {
+		return killgrave.Config{}, err
+
+	}
+
+	if err := configureLogging(cmd, &cfg); err != nil {
+		return killgrave.Config{}, err
+	}
+
+	return cfg, nil
 }
 
 func configureProxyMode(cmd *cobra.Command, cfg *killgrave.Config) error {
@@ -218,3 +232,17 @@ func configureProxyMode(cmd *cobra.Command, cfg *killgrave.Config) error {
 	cfg.ConfigureProxy(pMode, url)
 	return nil
 }
+
+func configureLogging(cmd *cobra.Command, cfg *killgrave.Config) error {
+	logLevel, err := cmd.Flags().GetString(_loglevelFlag)
+	if err != nil {
+		return err
+	}
+	logrusLogLevel, err := log.ParseLevel(logLevel)
+	if err != nil {
+		return err
+	}
+
+	cfg.Log.Level = logrusLogLevel
+	return nil
+}

internal/config.go

@@ -7,6 +7,7 @@ import (
 	"os"
 	"path"
 
+	log "github.com/sirupsen/logrus"
 	"gopkg.in/yaml.v2"
 )
 
@@ -19,6 +20,13 @@ type Config struct {
 	Proxy         ConfigProxy `yaml:"proxy"`
 	Secure        bool        `yaml:"secure"`
 	Watcher       bool        `yaml:"watcher"`
+	Log           ConfigLog   `yaml:"log"`
+}
+
+// ConfigLog is a representation of the log section of the yaml
+// This should include configurations for future features for logging (output format, dump file, etc)
+type ConfigLog struct {
+	Level log.Level `yaml:"level"`
 }
 
 // ConfigCORS representation of section CORS of the yaml

internal/config_test.go

@@ -4,6 +4,7 @@ import (
 	"errors"
 	"testing"
 
+	log "github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -107,6 +108,9 @@ func validConfig() Config {
 		},
 		Watcher: true,
 		Secure:  true,
+		Log: ConfigLog{
+			Level: log.InfoLevel,
+		},
 	}
 }
 

internal/loghelper.go

@@ -0,0 +1,14 @@
+package killgrave
+
+import (
+	"net/http"
+
+	log "github.com/sirupsen/logrus"
+)
+
+func LogFieldsFromRequest(req *http.Request) log.Fields {
+	return log.Fields{
+		"method": req.Method,
+		"url":    req.URL,
+	}
+}

internal/server/http/handler.go

@@ -2,10 +2,11 @@ package http
 
 import (
 	"io"
-	"log"
 	"net/http"
 	"os"
 	"time"
+
+	log "github.com/sirupsen/logrus"
 )
 
 // ImposterHandler create specific handler for the received imposter
@@ -18,6 +19,7 @@ func ImposterHandler(i Imposter) http.HandlerFunc {
 		writeHeaders(res, w)
 		w.WriteHeader(res.Status)
 		writeBody(i, res, w)
+		log.WithFields(i.LogFields()).Debugf("Request matched handler")
 	}
 }
 
@@ -43,15 +45,15 @@ func writeBody(i Imposter, r Response, w http.ResponseWriter) {
 
 func fetchBodyFromFile(bodyFile string) (bytes []byte) {
 	if _, err := os.Stat(bodyFile); os.IsNotExist(err) {
-		log.Printf("the body file %s not found\n", bodyFile)
+		log.Warnf("the body file %s not found\n", bodyFile)
 		return
 	}
 
 	f, _ := os.Open(bodyFile)
 	defer f.Close()
 	bytes, err := io.ReadAll(f)
 	if err != nil {
-		log.Printf("imposible read the file %s: %v\n", bodyFile, err)
+		log.Warnf("imposible read the file %s: %v\n", bodyFile, err)
 	}
 	return
 }

internal/server/http/imposter.go

@@ -10,6 +10,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	log "github.com/sirupsen/logrus"
 	"gopkg.in/yaml.v2"
 )
 
@@ -209,3 +210,11 @@ func (ifs ImposterFs) unmarshalImposters(imposterConfig ImposterConfig) ([]Impos
 
 	return imposters, nil
 }
+
+func (i Imposter) LogFields() log.Fields {
+	return log.Fields{
+		"endpoint": i.Request.Endpoint,
+		"method":   i.Request.Method,
+		"path":     i.Path,
+	}
+}

internal/server/http/route_matchers.go

@@ -5,12 +5,14 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"os"
 	"path/filepath"
 
+	killgrave "github.com/friendsofgo/killgrave/internal"
+
 	"github.com/gorilla/mux"
+	log "github.com/sirupsen/logrus"
 	"github.com/xeipuuv/gojsonschema"
 )
 
@@ -19,9 +21,8 @@ func MatcherBySchema(imposter Imposter) mux.MatcherFunc {
 	return func(req *http.Request, rm *mux.RouteMatch) bool {
 		err := validateSchema(imposter, req)
 
-		// TODO: inject the logger
 		if err != nil {
-			log.Println(err)
+			log.WithFields(killgrave.LogFieldsFromRequest(req)).Warn(err)
 			return false
 		}
 		return true

internal/server/http/server.go

@@ -4,13 +4,14 @@ import (
 	"context"
 	"crypto/tls"
 	_ "embed"
+	"fmt"
 	"errors"
-	"log"
 	"net/http"
 
 	killgrave "github.com/friendsofgo/killgrave/internal"
 	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
+	log "github.com/sirupsen/logrus"
 )
 
 //go:embed cert/server.key
@@ -82,6 +83,7 @@ func PrepareAccessControl(config killgrave.ConfigCORS) (h []handlers.CORSOption)
 func (s *Server) Build() error {
 	if s.proxy.mode == killgrave.ProxyAll {
 		// not necessary load the imposters if you will use the tool as a proxy
+		log.Infoln("ProxyAll mode enabled, no imposter will be used")
 		s.router.PathPrefix("/").HandlerFunc(s.proxy.Handler())
 		return nil
 	}
@@ -99,10 +101,14 @@ loop:
 		}
 
 		s.addImposterHandler(imposters)
-		log.Printf("imposter %s loaded\n", imposters[0].Path)
+		log.Infof("imposter %s loaded\n", imposters[0].Path)
 	}
 	if s.proxy.mode == killgrave.ProxyMissing {
+		log.Infof("Proxying missed requests to: %v", s.proxy.url)
 		s.router.NotFoundHandler = s.proxy.Handler()
+	} else {
+		log.Infoln("No proxy has been configured for non-matching requests, defaulting to a 404 response")
+		s.router.NotFoundHandler = s.defaultNotFoundHandler()
 	}
 	return nil
 }
@@ -115,7 +121,7 @@ func (s *Server) Run() {
 		if s.secure {
 			tlsString = "(TLS mode)"
 		}
-		log.Printf("The fake server is on tap now: %s%s\n", s.httpServer.Addr, tlsString)
+		log.Infof("The fake server is on tap now: %s%s\n", s.httpServer.Addr, tlsString)
 		err := s.run(s.secure)
 		if !errors.Is(err, http.ErrServerClosed) {
 			log.Fatal(err)
@@ -136,15 +142,14 @@ func (s *Server) run(secure bool) error {
 	s.httpServer.TLSConfig = &tls.Config{
 		Certificates: []tls.Certificate{cert},
 	}
-
 	return s.httpServer.ListenAndServeTLS("", "")
 }
 
 // Shutdown shutdowns the current http server
 func (s *Server) Shutdown() error {
-	log.Println("stopping server...")
+	log.Info("stopping server...")
 	if err := s.httpServer.Shutdown(context.TODO()); err != nil {
-		log.Fatalf("Server Shutdown Failed:%+v", err)
+		return fmt.Errorf("Server Shutdown Failed:%+v", err)
 	}
 
 	return nil
@@ -167,9 +172,19 @@ func (s *Server) addImposterHandler(imposters []Imposter) {
 				r.Queries(k, v)
 			}
 		}
+		log.WithFields(imposter.LogFields()).Debugln("imposter loaded")
+	}
+}
+
+func (s *Server) defaultNotFoundHandler() http.HandlerFunc {
+	return func(w http.ResponseWriter, r *http.Request) {
+		log.WithFields(killgrave.LogFieldsFromRequest(r)).Debugf("Request didn't match any imposter, and proxyMode is %v", s.proxy.mode)
+		w.WriteHeader(http.StatusNotFound)
+		w.Write([]byte("404 page not found\n"))
 	}
 }
 
+// not used?
 func (s *Server) handleAll(h http.HandlerFunc) {
 	s.router.PathPrefix("/").HandlerFunc(h)
 }

internal/server/http/server_test.go

@@ -3,7 +3,6 @@ package http
 import (
 	"crypto/tls"
 	"io"
-	"log"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -12,6 +11,7 @@ import (
 
 	killgrave "github.com/friendsofgo/killgrave/internal"
 	"github.com/gorilla/mux"
+	log "github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )

internal/test/testdata/config.yml

@@ -9,3 +9,5 @@ cors:
   allow_credentials: true
 watcher: true
 secure: true
+log:
+  level: "info"