diff --git a/api/api.go b/api/api.go index afb89df..d32413f 100644 --- a/api/api.go +++ b/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) } } diff --git a/go.mod b/go.mod index 085a1c6..c44181e 100644 --- a/go.mod +++ b/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 ) diff --git a/go.sum b/go.sum index cdec086..3ff8f7b 100644 --- a/go.sum +++ b/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= diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 0000000..0e27fc3 --- /dev/null +++ b/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() + } + }) +} diff --git a/main.go b/main.go index c869bf6..63e8bde 100644 --- a/main.go +++ b/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)