Structured logging

9 files changed, 113 insertions, 40 deletions

diff --git a/README.md b/README.md
index a99f8510..b33a7ff4 100644
--- a/README.md
+++ b/README.md
@@ -109,6 +109,12 @@ $ make
 $ ./gitlab-pages -listen-http ":8090" -metrics-address ":9235" -pages-root path/to/gitlab/shared/pages -pages-domain example.com
 ```
 
+### Structured logging
+
+You can use the `-log-format json` option to make GitLab Pages output
+JSON-structured logs. This makes it easer to parse and search logs
+with tools such as [ELK](https://www.elastic.co/elk-stack).
+
 ### Cross-origin requests
 
 GitLab Pages defaults to allowing cross-origin requests for any resource it
diff --git a/app.go b/app.go
index b2b09060..c7592701 100644
--- a/app.go
+++ b/app.go
@@ -2,7 +2,6 @@ package main
 
 import (
 	"crypto/tls"
-	"log"
 	"net"
 	"net/http"
 	"strconv"
@@ -14,6 +13,7 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/rs/cors"
+	log "github.com/sirupsen/logrus"
 
 	"gitlab.com/gitlab-org/gitlab-pages/internal/artifact"
 	"gitlab.com/gitlab-org/gitlab-pages/internal/httperrors"
@@ -151,7 +151,7 @@ func (a *theApp) Run() {
 			defer wg.Done()
 			err := listenAndServe(fd, a.ServeHTTP, a.HTTP2, nil)
 			if err != nil {
-				log.Fatal(err)
+				fatal(err)
 			}
 		}(fd)
 	}
@@ -163,7 +163,7 @@ func (a *theApp) Run() {
 			defer wg.Done()
 			err := listenAndServeTLS(fd, a.RootCertificate, a.RootKey, a.ServeHTTP, a.ServeTLS, a.HTTP2)
 			if err != nil {
-				log.Fatal(err)
+				fatal(err)
 			}
 		}(fd)
 	}
@@ -175,7 +175,7 @@ func (a *theApp) Run() {
 			defer wg.Done()
 			err := listenAndServe(fd, a.ServeProxy, a.HTTP2, nil)
 			if err != nil {
-				log.Fatal(err)
+				fatal(err)
 			}
 		}(fd)
 	}
@@ -189,7 +189,7 @@ func (a *theApp) Run() {
 			handler := promhttp.HandlerFor(prometheus.DefaultGatherer, promhttp.HandlerOpts{}).ServeHTTP
 			err := listenAndServe(fd, handler, false, nil)
 			if err != nil {
-				log.Fatal(err)
+				fatal(err)
 			}
 		}(a.ListenMetrics)
 	}
@@ -200,14 +200,17 @@ func (a *theApp) Run() {
 }
 
 func runApp(config appConfig) {
-	if err := mimedb.LoadTypes(); err != nil {
-		log.Printf("WARNING: Loading extended MIME database failed: %v", err)
-	}
-
 	a := theApp{appConfig: config}
 
 	if config.ArtifactsServer != "" {
 		a.Artifact = artifact.New(config.ArtifactsServer, config.ArtifactsServerTimeout, config.Domain)
 	}
+
+	configureLogging(config.LogFormat)
+
+	if err := mimedb.LoadTypes(); err != nil {
+		log.WithError(err).Warn("Loading extended MIME database failed")
+	}
+
 	a.Run()
 }
diff --git a/app_config.go b/app_config.go
index dd47ed01..2f8cbd1f 100644
--- a/app_config.go
+++ b/app_config.go
@@ -17,4 +17,6 @@ type appConfig struct {
 	StatusPath   string
 
 	DisableCrossOriginRequests bool
+
+	LogFormat string
 }
diff --git a/daemon.go b/daemon.go
index bbe69118..8f71940f 100644
--- a/daemon.go
+++ b/daemon.go
@@ -5,7 +5,6 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
 	"os"
 	"os/exec"
 	"os/signal"
@@ -13,6 +12,7 @@ import (
 	"syscall"
 
 	"github.com/kardianos/osext"
+	log "github.com/sirupsen/logrus"
 )
 
 const daemonRunProgram = "gitlab-pages-unprivileged"
@@ -22,12 +22,15 @@ func daemonMain() {
 		return
 	}
 
-	log.Printf("Starting the daemon as unprivileged user (uid: %d, gid: %d)...", syscall.Getuid(), syscall.Getgid())
+	log.WithFields(log.Fields{
+		"uid": syscall.Getuid(),
+		"gid": syscall.Getgid(),
+	}).Print("starting the daemon as unprivileged user")
 
 	// read the configuration from the pipe "ExtraFiles"
 	var config appConfig
 	if err := json.NewDecoder(os.NewFile(3, "options")).Decode(&config); err != nil {
-		log.Fatalln(err)
+		fatal(err)
 	}
 	runApp(config)
 	os.Exit(0)
@@ -174,10 +177,14 @@ func daemonize(config appConfig, uid, gid uint) {
 	var err error
 	defer func() {
 		if err != nil {
-			log.Fatalln(err)
+			fatal(err)
 		}
 	}()
-	log.Printf("Running the daemon as unprivileged user (uid:%d, gid: %d)...", uid, gid)
+
+	log.WithFields(log.Fields{
+		"uid": uid,
+		"gid": gid,
+	}).Print("running the daemon as unprivileged user")
 
 	cmd, err := daemonReexec(uid, gid, daemonRunProgram)
 	if err != nil {
@@ -188,7 +195,7 @@ func daemonize(config appConfig, uid, gid uint) {
 	// Run daemon in chroot environment
 	temporaryExecutable, err := daemonChroot(cmd)
 	if err != nil {
-		log.Println("Chroot failed", err)
+		log.WithError(err).Print("chroot failed")
 		return
 	}
 	defer os.Remove(temporaryExecutable)
@@ -211,7 +218,7 @@ func daemonize(config appConfig, uid, gid uint) {
 
 	// Start the process
 	if err = cmd.Start(); err != nil {
-		log.Println("Start failed", err)
+		log.WithError(err).Print("start failed")
 		return
 	}
 
diff --git a/domains.go b/domains.go
index 000aa42e..7428ea99 100644
--- a/domains.go
+++ b/domains.go
@@ -4,12 +4,12 @@ import (
 	"bytes"
 	"errors"
 	"io/ioutil"
-	"log"
 	"os"
 	"path/filepath"
 	"strings"
 	"time"
 
+	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitlab-pages/metrics"
 )
 
@@ -80,7 +80,9 @@ func (d domains) readProjects(rootDomain, group string) (count int) {
 
 	fis, err := projects.Readdir(0)
 	if err != nil {
-		log.Println("Failed to Readdir for ", group, ":", err)
+		log.WithError(err).WithFields(log.Fields{
+			"group": group,
+		}).Print("readdir failed")
 	}
 
 	for _, project := range fis {
@@ -106,7 +108,7 @@ func (d domains) ReadGroups(rootDomain string) error {
 
 	fis, err := groups.Readdir(0)
 	if err != nil {
-		log.Println("Failed to Readdir for .:", err)
+		log.WithError(err).Print("readdir failed")
 	}
 
 	for _, group := range fis {
@@ -132,7 +134,7 @@ func watchDomains(rootDomain string, updater domainsUpdater, interval time.Durat
 		// Read the update file
 		update, err := ioutil.ReadFile(".update")
 		if err != nil && !os.IsNotExist(err) {
-			log.Println("Failed to read update timestamp:", err)
+			log.WithError(err).Print("failed to read update timestamp")
 			time.Sleep(interval)
 			continue
 		}
@@ -147,8 +149,13 @@ func watchDomains(rootDomain string, updater domainsUpdater, interval time.Durat
 		started := time.Now()
 		domains := make(domains)
 		domains.ReadGroups(rootDomain)
-		duration := time.Since(started)
-		log.Println("Updated", len(domains), "domains in", duration, "Hash:", update)
+		duration := time.Since(started).Seconds()
+
+		log.WithFields(log.Fields{
+			"domains":  len(domains),
+			"duration": duration,
+			"hash":     update,
+		}).Print("updated domains")
 
 		if updater != nil {
 			updater(domains)
diff --git a/helpers.go b/helpers.go
index edcf583d..b418eec3 100644
--- a/helpers.go
+++ b/helpers.go
@@ -2,7 +2,6 @@ package main
 
 import (
 	"io/ioutil"
-	"log"
 	"net"
 	"strings"
 )
@@ -10,7 +9,7 @@ import (
 func readFile(file string) (result []byte) {
 	result, err := ioutil.ReadFile(file)
 	if err != nil {
-		log.Fatalln(err)
+		fatal(err)
 	}
 	return
 }
@@ -18,12 +17,12 @@ func readFile(file string) (result []byte) {
 func createSocket(addr string) (l net.Listener, fd uintptr) {
 	l, err := net.Listen("tcp", addr)
 	if err != nil {
-		log.Fatalln(err)
+		fatal(err)
 	}
 
 	f, err := l.(*net.TCPListener).File()
 	if err != nil {
-		log.Fatalln(err)
+		fatal(err)
 	}
 
 	fd = f.Fd()
diff --git a/helpers_test.go b/helpers_test.go
index 9f372224..4d732d81 100644
--- a/helpers_test.go
+++ b/helpers_test.go
@@ -5,7 +5,6 @@ import (
 	"crypto/tls"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"os"
@@ -14,6 +13,7 @@ import (
 	"testing"
 	"time"
 
+	log "github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -36,7 +36,7 @@ func setUpTests() {
 
 	err := os.Chdir("shared/pages")
 	if err != nil {
-		log.Println("Chdir:", err)
+		log.WithError(err).Print("chdir")
 	} else {
 		chdirSet = true
 	}
diff --git a/logging.go b/logging.go
index bee171b2..dd282b1a 100644
--- a/logging.go
+++ b/logging.go
@@ -4,8 +4,26 @@ import (
 	"fmt"
 	"net/http"
 	"time"
+
+	log "github.com/sirupsen/logrus"
+)
+
+var (
+	accessLogFormat = "text"
+	logrusEntry     = log.WithField("system", "http")
 )
 
+func configureLogging(format string) {
+	switch format {
+	case "json":
+		log.SetFormatter(&log.JSONFormatter{})
+		accessLogFormat = "json"
+	default:
+		log.SetFormatter(&log.TextFormatter{})
+		accessLogFormat = "text"
+	}
+}
+
 type loggingResponseWriter struct {
 	rw      http.ResponseWriter
 	status  int
@@ -43,10 +61,33 @@ func (l *loggingResponseWriter) WriteHeader(status int) {
 }
 
 func (l *loggingResponseWriter) Log(r *http.Request) {
-	duration := time.Since(l.started)
-	fmt.Printf("%s %s - - [%s] %q %d %d %q %q %f\n",
-		r.Host, r.RemoteAddr, l.started,
-		fmt.Sprintf("%s %s %s", r.Method, r.RequestURI, r.Proto),
-		l.status, l.written, r.Referer(), r.UserAgent(), duration.Seconds(),
-	)
+	fields := log.Fields{
+		"host":       r.Host,
+		"remoteAddr": r.RemoteAddr,
+		"method":     r.Method,
+		"uri":        r.RequestURI,
+		"proto":      r.Proto,
+		"status":     l.status,
+		"written":    l.written,
+		"referer":    r.Referer(),
+		"userAgent":  r.UserAgent(),
+		"duration":   time.Since(l.started).Seconds(),
+	}
+
+	switch accessLogFormat {
+	case "text":
+		fmt.Printf("%s %s - - [%s] %q %d %d %q %q %f\n",
+			fields["host"], fields["remoteAddr"], l.started,
+			fmt.Sprintf("%s %s %s", fields["method"], fields["uri"], fields["proto"]),
+			fields["status"], fields["written"], fields["referer"], fields["userAgent"], fields["duration"],
+		)
+	case "json":
+		logrusEntry.WithFields(fields).Info("access")
+	default:
+		panic("invalid access log format")
+	}
+}
+
+func fatal(err error) {
+	log.WithError(err).Fatal()
 }
diff --git a/main.go b/main.go
index 5ca5470b..d71c1e8c 100644
--- a/main.go
+++ b/main.go
@@ -2,12 +2,14 @@ package main
 
 import (
 	"errors"
-	"log"
+	"fmt"
 	"net/url"
 	"os"
 	"strings"
 
 	"github.com/namsral/flag"
+
+	log "github.com/sirupsen/logrus"
 )
 
 // VERSION stores the information about the semantic version of application
@@ -29,6 +31,7 @@ var (
 	metricsAddress         = flag.String("metrics-address", "", "The address to listen on for metrics requests")
 	daemonUID              = flag.Uint("daemon-uid", 0, "Drop privileges to this user")
 	daemonGID              = flag.Uint("daemon-gid", 0, "Drop privileges to this group")
+	logFormat              = flag.String("log-format", "text", "The log output format: 'text' or 'json'")
 
 	disableCrossOriginRequests     = flag.Bool("disable-cross-origin-requests", false, "Disable cross-origin requests")
 	errArtifactSchemaUnsupported   = errors.New("artifacts-server scheme must be either http:// or https://")
@@ -43,6 +46,7 @@ func configFromFlags() appConfig {
 	config.HTTP2 = *useHTTP2
 	config.DisableCrossOriginRequests = *disableCrossOriginRequests
 	config.StatusPath = *pagesStatus
+	config.LogFormat = *logFormat
 
 	if *pagesRootCert != "" {
 		config.RootCertificate = readFile(*pagesRootCert)
@@ -89,12 +93,17 @@ func appMain() {
 
 	printVersion(*showVersion, VERSION)
 
-	log.Printf("GitLab Pages Daemon %s (%s)", VERSION, REVISION)
-	log.Printf("URL: https://gitlab.com/gitlab-org/gitlab-pages\n")
+	configureLogging(*logFormat)
+
+	log.WithFields(log.Fields{
+		"version":  VERSION,
+		"revision": REVISION,
+	}).Print("GitLab Pages Daemon")
+	log.Printf("URL: https://gitlab.com/gitlab-org/gitlab-pages")
 
 	err := os.Chdir(*pagesRoot)
 	if err != nil {
-		log.Fatalln(err)
+		fatal(err)
 	}
 
 	config := configFromFlags()
@@ -133,8 +142,7 @@ func appMain() {
 
 func printVersion(showVersion bool, version string) {
 	if showVersion {
-		log.SetFlags(0)
-		log.Printf(version)
+		fmt.Fprintf(os.Stderr, version)
 		os.Exit(0)
 	}
 }