Add structured logging

api/api.go

@@ -3,10 +3,12 @@ package api
 import (
 	"encoding/json"
 	"github.com/gorilla/mux"
-	"log"
+	"gitlab.hpi.de/codeocean/codemoon/poseidon/logging"
 	"net/http"
 )
 
+var log = logging.GetLogger("api")
+
 // NewRouter returns an HTTP handler (http.Handler) which can be
 // used by the net/http package to serve the routes of our API. It
 // always returns a router for the newest version of our API. We
@@ -16,7 +18,9 @@ func NewRouter() http.Handler {
 	router := mux.NewRouter()
 	// this can later be restricted to a specific host with
 	// `router.Host(...)` and to HTTPS with `router.Schemes("https")`
-	return newRouterV1(router)
+	router = newRouterV1(router)
+	router.Use(logging.HTTPLoggingMiddleware)
+	return router
 }
 
 // newRouterV1 returns a subrouter containing the routes of version
@@ -31,12 +35,12 @@ func writeJson(writer http.ResponseWriter, content interface{}) {
 	writer.Header().Set("Content-Type", "application/json")
 	response, err := json.Marshal(content)
 	if err != nil {
-		log.Printf("JSON marshal error: %v\n", err)
+		log.WithError(err).Warn("JSON marshal error")
 		http.Error(writer, err.Error(), http.StatusInternalServerError)
 		return
 	}
 	if _, err := writer.Write(response); err != nil {
-		log.Printf("Error writing JSON to response: %v\n", err)
+		log.WithError(err).Warn("Error writing JSON to response")
 		http.Error(writer, err.Error(), http.StatusInternalServerError)
 	}
 }

go.mod

@@ -4,6 +4,8 @@ go 1.16
 
 require (
 	github.com/gorilla/mux v1.8.0
+	github.com/sirupsen/logrus v1.8.1
 	github.com/stretchr/testify v1.7.0
+	golang.org/x/sys v0.0.0-20210426230700-d19ff857e887 // indirect
 	gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b
 )

go.sum

@@ -1,12 +1,19 @@
-github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8=
 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=
 github.com/gorilla/mux v1.8.0 h1:i40aqfkR1h2SlN9hojwV5ZA91wcXFOvkdNIeFDP5koI=
 github.com/gorilla/mux v1.8.0/go.mod h1:DVbg23sWSpFRCP0SfiEN6jmj59UnW/n46BH5rLB71So=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE=
+github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210426230700-d19ff857e887 h1:dXfMednGJh/SUUFjTLsWJz3P+TQt9qnR11GgeI3vWKs=
+golang.org/x/sys v0.0.0-20210426230700-d19ff857e887/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

logging/logging.go

@@ -0,0 +1,72 @@
+package logging
+
+import (
+	"github.com/sirupsen/logrus"
+	"net/http"
+	"os"
+	"time"
+)
+
+var log = &logrus.Logger{
+	Out: os.Stderr,
+	Formatter: &logrus.TextFormatter{
+		DisableColors: true,
+		FullTimestamp: true,
+	},
+	Hooks: make(logrus.LevelHooks),
+	Level: logrus.InfoLevel,
+}
+
+func InitializeLogging(loglevel string) {
+	level, err := logrus.ParseLevel(loglevel)
+	if err != nil {
+		log.WithError(err).Fatal("Error parsing loglevel")
+		return
+	}
+	log.SetLevel(level)
+}
+
+func GetLogger(pkg string) *logrus.Entry {
+	return log.WithField("package", pkg)
+}
+
+// loggingResponseWriter wraps the default http.ResponseWriter and catches the status code
+// that is written
+type loggingResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+func NewLoggingResponseWriter(w http.ResponseWriter) *loggingResponseWriter {
+	return &loggingResponseWriter{w, http.StatusOK}
+}
+
+func (writer *loggingResponseWriter) WriteHeader(code int) {
+	writer.statusCode = code
+	writer.ResponseWriter.WriteHeader(code)
+}
+
+// HTTPLoggingMiddleware returns an http.Handler that logs different information about every request
+func HTTPLoggingMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now().UTC()
+		path := r.URL.Path
+
+		lrw := NewLoggingResponseWriter(w)
+		next.ServeHTTP(lrw, r)
+
+		latency := time.Now().UTC().Sub(start)
+		logEntry := log.WithFields(logrus.Fields{
+			"code":       lrw.statusCode,
+			"method":     r.Method,
+			"path":       path,
+			"duration":   latency,
+			"user_agent": r.UserAgent(),
+		})
+		if lrw.statusCode >= http.StatusInternalServerError {
+			logEntry.Warn()
+		} else {
+			logEntry.Debug()
+		}
+	})
+}

main.go

@@ -5,15 +5,18 @@ import (
 	"fmt"
 	"gitlab.hpi.de/codeocean/codemoon/poseidon/api"
 	"gitlab.hpi.de/codeocean/codemoon/poseidon/config"
-	"log"
+	"gitlab.hpi.de/codeocean/codemoon/poseidon/logging"
 	"net/http"
 	"os"
 	"os/signal"
 	"time"
 )
 
+var log = logging.GetLogger("main")
+
 func main() {
 	config.InitConfig()
+	logging.InitializeLogging(config.Config.Logger.Level)
 
 	server := &http.Server{
 		Addr:         fmt.Sprintf("%s:%d", config.Config.Server.Address, config.Config.Server.Port),
@@ -22,12 +25,14 @@ func main() {
 		IdleTimeout:  time.Second * 60,
 		Handler:      api.NewRouter(),
 	}
+
+	log.WithField("address", server.Addr).Info("Starting server")
 	go func() {
 		if err := server.ListenAndServe(); err != nil {
 			if err == http.ErrServerClosed {
-				log.Println(err)
+				log.WithError(err).Info("Server closed")
 			} else {
-				log.Fatal("Error during listening and serving: ", err)
+				log.WithError(err).Fatal("Error during listening and serving")
 			}
 		}
 	}()
@@ -36,7 +41,7 @@ func main() {
 	signals := make(chan os.Signal, 1)
 	signal.Notify(signals, os.Interrupt)
 	<-signals
-	log.Println("Received SIGINT, shutting down ...")
+	log.Info("Received SIGINT, shutting down ...")
 
 	// shutdown the server but wait up to 15 seconds to close remaining connections
 	ctx, cancel := context.WithTimeout(context.Background(), 15*time.Second)