implement structured logging

api/api.go

@@ -3,7 +3,6 @@ package api
 
 import (
 	"fmt"
-	"log"
 	"net/http"
 	"sort"
 	"strconv"
@@ -15,6 +14,7 @@ import (
 	"github.com/aptly-dev/aptly/query"
 	"github.com/aptly-dev/aptly/task"
 	"github.com/gin-gonic/gin"
+	"github.com/rs/zerolog/log"
 )
 
 // Lock order acquisition (canonical):
@@ -155,7 +155,7 @@ func maybeRunTaskInBackground(c *gin.Context, name string, resources []string, p
 	// Run this task in background if configured globally or per-request
 	background := truthy(c.DefaultQuery("_async", strconv.FormatBool(context.Config().AsyncAPI)))
 	if background {
-		log.Println("Executing task asynchronously")
+		log.Info().Msg("Executing task asynchronously")
 		task, conflictErr := runTaskInBackground(name, resources, proc)
 		if conflictErr != nil {
 			AbortWithJSONError(c, 409, conflictErr)
@@ -163,7 +163,7 @@ func maybeRunTaskInBackground(c *gin.Context, name string, resources []string, p
 		}
 		c.JSON(202, task)
 	} else {
-		log.Println("Executing task synchronously")
+		log.Info().Msg("Executing task synchronously")
 		out := context.Progress()
 		detail := task.Detail{}
 		retValue, err := proc(out, &detail)

api/middleware.go

@@ -9,20 +9,36 @@ import (
 
 	"github.com/gin-gonic/gin"
 	"github.com/prometheus/client_golang/prometheus"
+	"github.com/rs/zerolog/log"
 )
 
 // Only use base path as label value (e.g.: /api/repos) because of time series cardinality
 // See https://prometheus.io/docs/practices/naming/#labels
 func getBasePath(c *gin.Context) string {
-	return fmt.Sprintf("%s%s", getURLSegment(c.Request.URL.Path, 0), getURLSegment(c.Request.URL.Path, 1))
+	segment0, err := getURLSegment(c.Request.URL.Path, 0)
+	if err != nil {
+		return "/"
+	}
+	segment1, err := getURLSegment(c.Request.URL.Path, 1)
+	if err != nil {
+		return *segment0
+	}
+
+	return *segment0 + *segment1
 }
 
-func getURLSegment(url string, idx int) string {
-	var urlSegments = strings.Split(url, "/")
-
+func getURLSegment(url string, idx int) (*string, error) {
+	urlSegments := strings.Split(url, "/")
 	// Remove segment at index 0 because it's an empty string
-	var segmentAtIndex = urlSegments[1:cap(urlSegments)][idx]
-	return fmt.Sprintf("/%s", segmentAtIndex)
+	urlSegments = urlSegments[1:cap(urlSegments)]
+
+	if len(urlSegments) <= idx {
+		return nil, fmt.Errorf("index %d out of range, only has %d url segments", idx, len(urlSegments))
+	}
+
+	segmentAtIndex := urlSegments[idx]
+	s := fmt.Sprintf("/%s", segmentAtIndex)
+	return &s, nil
 }
 
 func instrumentHandlerInFlight(g *prometheus.GaugeVec, pathFunc func(*gin.Context) string) func(*gin.Context) {
@@ -62,3 +78,39 @@ func instrumentHandlerDuration(obs prometheus.ObserverVec, pathFunc func(*gin.Co
 		obs.WithLabelValues(strconv.Itoa(c.Writer.Status()), c.Request.Method, pathFunc(c)).Observe(time.Since(now).Seconds())
 	}
 }
+
+// JSONLogger is a gin middleware that takes an instance of Logger and uses it for writing access
+// logs that include error messages if there are any.
+func JSONLogger() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		// Start timer
+		start := time.Now()
+		path := c.Request.URL.Path
+		raw := c.Request.URL.RawQuery
+
+		// Process request
+		c.Next()
+
+		ts := time.Now()
+		if raw != "" {
+			path = path + "?" + raw
+		}
+
+		errorMessage := strings.TrimSuffix(c.Errors.ByType(gin.ErrorTypePrivate).String(), "\n")
+		l := log.With().Str("remote", c.ClientIP()).Logger().
+			With().Str("method", c.Request.Method).Logger().
+			With().Str("path", path).Logger().
+			With().Str("protocol", c.Request.Proto).Logger().
+			With().Str("code", fmt.Sprint(c.Writer.Status())).Logger().
+			With().Str("latency", ts.Sub(start).String()).Logger().
+			With().Str("agent", c.Request.UserAgent()).Logger()
+
+		if c.Writer.Status() >= 400 && c.Writer.Status() < 500 {
+			l.Warn().Msg(errorMessage)
+		} else if c.Writer.Status() >= 500 {
+			l.Error().Msg(errorMessage)
+		} else {
+			l.Info().Msg(errorMessage)
+		}
+	}
+}

api/middleware_test.go

@@ -0,0 +1,255 @@
+package api
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"sync/atomic"
+
+	"github.com/aptly-dev/aptly/utils"
+	"github.com/gin-gonic/gin"
+	. "gopkg.in/check.v1"
+)
+
+type MiddlewareSuite struct {
+	router    http.Handler
+	context   *gin.Context
+	logReader *os.File
+	logWriter *os.File
+}
+
+var _ = Suite(&MiddlewareSuite{})
+
+func (s *MiddlewareSuite) SetUpTest(c *C) {
+	r, w, err := os.Pipe()
+	c.Assert(err, IsNil)
+
+	utils.SetupJSONLogger("debug", w)
+	mw := JSONLogger()
+
+	router := gin.New()
+	router.UseRawPath = true
+	router.Use(mw)
+	router.Use(gin.Recovery(), gin.ErrorLogger())
+
+	root := router.Group("/api")
+	isReady := &atomic.Value{}
+	isReady.Store(false)
+	root.GET("/ready", apiReady(isReady))
+	root.GET("/healthy", apiHealthy)
+
+	s.router = router
+	s.logReader = r
+	s.logWriter = w
+}
+
+func (s *MiddlewareSuite) TearDownTest(c *C) {
+	s.router = nil
+	s.context = nil
+	s.logReader = nil
+	s.logWriter = nil
+}
+
+func (s *MiddlewareSuite) HTTPRequest(method string, url string, body io.Reader) {
+	recorder := httptest.NewRecorder()
+	s.context, _ = gin.CreateTestContext(recorder)
+	req, _ := http.NewRequestWithContext(s.context, method, url, body)
+	s.context.Request = req
+	req.Header.Add("Content-Type", "application/json")
+	s.router.ServeHTTP(httptest.NewRecorder(), req)
+}
+
+func (s *MiddlewareSuite) TestJSONMiddleware4xx(c *C) {
+	outC := make(chan string)
+	go func() {
+		var buf bytes.Buffer
+		io.Copy(&buf, s.logReader)
+		fmt.Println(buf.String())
+		outC <- buf.String()
+	}()
+
+	s.HTTPRequest(http.MethodGet, "/", nil)
+	s.logWriter.Close()
+	capturedOutput := <-outC
+
+	var jsonMap map[string]interface{}
+	json.Unmarshal([]byte(capturedOutput), &jsonMap)
+
+	if val, ok := jsonMap["level"]; ok {
+		c.Check(val, Equals, "warn")
+	} else {
+		c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput)
+	}
+
+	if val, ok := jsonMap["method"]; ok {
+		c.Check(val, Equals, "GET")
+	} else {
+		c.Errorf("Log message didn't have a 'method' key, obtained %s", capturedOutput)
+	}
+
+	if val, ok := jsonMap["path"]; ok {
+		c.Check(val, Equals, "/")
+	} else {
+		c.Errorf("Log message didn't have a 'path' key, obtained %s", capturedOutput)
+	}
+
+	if val, ok := jsonMap["protocol"]; ok {
+		c.Check(val, Equals, "HTTP/1.1")
+	} else {
+		c.Errorf("Log message didn't have a 'protocol' key, obtained %s", capturedOutput)
+	}
+
+	if val, ok := jsonMap["code"]; ok {
+		c.Check(val, Equals, "404")
+	} else {
+		c.Errorf("Log message didn't have a 'code' key, obtained %s", capturedOutput)
+	}
+
+	if _, ok := jsonMap["remote"]; !ok {
+		c.Errorf("Log message didn't have a 'remote' key, obtained %s", capturedOutput)
+	}
+
+	if _, ok := jsonMap["latency"]; !ok {
+		c.Errorf("Log message didn't have a 'latency' key, obtained %s", capturedOutput)
+	}
+
+	if _, ok := jsonMap["agent"]; !ok {
+		c.Errorf("Log message didn't have a 'agent' key, obtained %s", capturedOutput)
+	}
+
+	if _, ok := jsonMap["time"]; !ok {
+		c.Errorf("Log message didn't have a 'time' key, obtained %s", capturedOutput)
+	}
+}
+
+func (s *MiddlewareSuite) TestJSONMiddleware2xx(c *C) {
+	outC := make(chan string)
+	go func() {
+		var buf bytes.Buffer
+		io.Copy(&buf, s.logReader)
+		fmt.Println(buf.String())
+		outC <- buf.String()
+	}()
+
+	s.HTTPRequest(http.MethodGet, "/api/healthy", nil)
+	s.logWriter.Close()
+	capturedOutput := <-outC
+
+	var jsonMap map[string]interface{}
+	json.Unmarshal([]byte(capturedOutput), &jsonMap)
+
+	if val, ok := jsonMap["level"]; ok {
+		c.Check(val, Equals, "info")
+	} else {
+		c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput)
+	}
+}
+
+func (s *MiddlewareSuite) TestJSONMiddleware5xx(c *C) {
+	outC := make(chan string)
+	go func() {
+		var buf bytes.Buffer
+		io.Copy(&buf, s.logReader)
+		fmt.Println(buf.String())
+		outC <- buf.String()
+	}()
+
+	s.HTTPRequest(http.MethodGet, "/api/ready", nil)
+	s.logWriter.Close()
+	capturedOutput := <-outC
+
+	var jsonMap map[string]interface{}
+	json.Unmarshal([]byte(capturedOutput), &jsonMap)
+
+	if val, ok := jsonMap["level"]; ok {
+		c.Check(val, Equals, "error")
+	} else {
+		c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput)
+	}
+}
+
+func (s *MiddlewareSuite) TestJSONMiddlewareRaw(c *C) {
+	outC := make(chan string)
+	go func() {
+		var buf bytes.Buffer
+		io.Copy(&buf, s.logReader)
+		fmt.Println(buf.String())
+		outC <- buf.String()
+	}()
+
+	s.HTTPRequest(http.MethodGet, "/api/healthy?test=raw", nil)
+	s.logWriter.Close()
+	capturedOutput := <-outC
+
+	var jsonMap map[string]interface{}
+	json.Unmarshal([]byte(capturedOutput), &jsonMap)
+
+	fmt.Println(capturedOutput)
+
+	if val, ok := jsonMap["level"]; ok {
+		c.Check(val, Equals, "info")
+	} else {
+		c.Errorf("Log message didn't have a 'level' key, obtained %s", capturedOutput)
+	}
+}
+
+func (s *MiddlewareSuite) TestGetBasePath(c *C) {
+	s.HTTPRequest(http.MethodGet, "", nil)
+	path := getBasePath(s.context)
+	c.Check(path, Equals, "/")
+
+	s.HTTPRequest(http.MethodGet, "/", nil)
+	path = getBasePath(s.context)
+	c.Check(path, Equals, "/")
+
+	s.HTTPRequest(http.MethodGet, "/api", nil)
+	path = getBasePath(s.context)
+	c.Check(path, Equals, "/api")
+
+	s.HTTPRequest(http.MethodGet, "/api/repos/testRepo", nil)
+	path = getBasePath(s.context)
+	c.Check(path, Equals, "/api/repos")
+}
+
+func (s *MiddlewareSuite) TestGetURLSegment(c *C) {
+	url := "/"
+	segment, err := getURLSegment(url, 0)
+	if err != nil {
+		c.Error(err)
+	}
+	c.Check(*segment, Equals, "/")
+
+	_, err = getURLSegment(url, 1)
+	if err == nil {
+		c.Error("Invalid return value")
+	}
+
+	url = "/api"
+	segment, err = getURLSegment(url, 0)
+	if err != nil {
+		c.Error(err)
+	}
+	c.Check(*segment, Equals, "/api")
+
+	_, err = getURLSegment(url, 1)
+	if err == nil {
+		c.Error("Invalid return value")
+	}
+
+	url = "/api/repos/testRepo"
+	segment, err = getURLSegment(url, 0)
+	if err != nil {
+		c.Error(err)
+	}
+	c.Check(*segment, Equals, "/api")
+
+	segment, err = getURLSegment(url, 1)
+	if err != nil {
+		c.Error(err)
+	}
+	c.Check(*segment, Equals, "/repos")
+}

api/mirror.go

@@ -2,7 +2,6 @@ package api
 
 import (
 	"fmt"
-	"log"
 	"net/http"
 	"sort"
 	"strings"
@@ -14,6 +13,7 @@ import (
 	"github.com/aptly-dev/aptly/query"
 	"github.com/aptly-dev/aptly/task"
 	"github.com/gin-gonic/gin"
+	"github.com/rs/zerolog/log"
 )
 
 func getVerifier(ignoreSignatures bool, keyRings []string) (pgp.Verifier, error) {
@@ -309,7 +309,7 @@ func apiMirrorsUpdate(c *gin.Context) {
 	b.Architectures = remote.Architectures
 	b.Components = remote.Components
 
-	log.Printf("%s: Starting mirror update\n", b.Name)
+	log.Info().Msgf("%s: Starting mirror update\n", b.Name)
 
 	if c.Bind(&b) != nil {
 		return
@@ -458,7 +458,7 @@ func apiMirrorsUpdate(c *gin.Context) {
 			}
 		}()
 
-		log.Printf("%s: Spawning background processes...\n", b.Name)
+		log.Info().Msgf("%s: Spawning background processes...\n", b.Name)
 		var wg sync.WaitGroup
 		for i := 0; i < context.Config().DownloadConcurrency; i++ {
 			wg.Add(1)
@@ -505,9 +505,9 @@ func apiMirrorsUpdate(c *gin.Context) {
 		}
 
 		// Wait for all download goroutines to finish
-		log.Printf("%s: Waiting for background processes to finish...\n", b.Name)
+		log.Info().Msgf("%s: Waiting for background processes to finish...\n", b.Name)
 		wg.Wait()
-		log.Printf("%s: Background processes finished\n", b.Name)
+		log.Info().Msgf("%s: Background processes finished\n", b.Name)
 		close(taskFinished)
 
 		for idx := range queue {
@@ -539,18 +539,18 @@ func apiMirrorsUpdate(c *gin.Context) {
 		}
 
 		if len(errors) > 0 {
-			log.Printf("%s: Unable to update because of previous errors\n", b.Name)
+			log.Info().Msgf("%s: Unable to update because of previous errors\n", b.Name)
 			return &task.ProcessReturnValue{Code: http.StatusInternalServerError, Value: nil}, fmt.Errorf("unable to update: download errors:\n  %s", strings.Join(errors, "\n  "))
 		}
 
-		log.Printf("%s: Finalizing download\n", b.Name)
+		log.Info().Msgf("%s: Finalizing download\n", b.Name)
 		remote.FinalizeDownload(collectionFactory, out)
 		err = collectionFactory.RemoteRepoCollection().Update(remote)
 		if err != nil {
 			return &task.ProcessReturnValue{Code: http.StatusInternalServerError, Value: nil}, fmt.Errorf("unable to update: %s", err)
 		}
 
-		log.Printf("%s: Mirror updated successfully!\n", b.Name)
+		log.Info().Msgf("%s: Mirror updated successfully!\n", b.Name)
 		return &task.ProcessReturnValue{Code: http.StatusNoContent, Value: nil}, nil
 	})
 }

api/router.go

@@ -2,11 +2,14 @@ package api
 
 import (
 	"net/http"
+	"os"
 	"sync/atomic"
 
 	ctx "github.com/aptly-dev/aptly/context"
+	"github.com/aptly-dev/aptly/utils"
 	"github.com/gin-gonic/gin"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
+	"github.com/rs/zerolog/log"
 )
 
 var context *ctx.AptlyContext
@@ -19,11 +22,23 @@ func apiMetricsGet() gin.HandlerFunc {
 
 // Router returns prebuilt with routes http.Handler
 func Router(c *ctx.AptlyContext) http.Handler {
+	router := gin.New()
 	context = c
 
-	router := gin.Default()
 	router.UseRawPath = true
-	router.Use(gin.ErrorLogger())
+
+	if c.Config().LogFormat == "json" {
+		c.StructuredLogging(true)
+		utils.SetupJSONLogger(c.Config().LogLevel, os.Stdout)
+		gin.DefaultWriter = utils.LogWriter{Logger: log.Logger}
+		router.Use(JSONLogger())
+	} else {
+		c.StructuredLogging(false)
+		utils.SetupDefaultLogger(c.Config().LogLevel)
+		router.Use(gin.Logger())
+	}
+
+	router.Use(gin.Recovery(), gin.ErrorLogger())
 
 	if c.Config().EnableMetricsEndpoint {
 		MetricsCollectorRegistrar.Register(router)