Merge branch 'an/structured-logging' into 'master'

Structured logging rebased

See merge request gitlab-org/gitlab-workhorse!236

_support/fake-auth-backend.go

@@ -2,9 +2,10 @@ package main
 
 import (
 	"fmt"
-	"log"
 	"net/http"
 	"os"
+
+	log "github.com/sirupsen/logrus"
 )
 
 func main() {

internal/artifacts/artifacts_test.go

 package artifacts
 
 import (
-	"log"
 	"os"
 	"testing"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/testhelper"
 )
 
 func TestMain(m *testing.M) {
 	cleanup, err := testhelper.BuildExecutables()
 	if err != nil {
-		log.Printf("Test setup: failed to build executables: %v", err)
+		log.WithError(err).Print("Test setup: failed to build executables")
 		os.Exit(1)
 	}
 

internal/artifacts/entry.go

@@ -4,7 +4,6 @@ import (
 	"bufio"
 	"fmt"
 	"io"
-	"log"
 	"mime"
 	"net/http"
 	"os"
@@ -13,6 +12,8 @@ import (
 	"strings"
 	"syscall"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/zipartifacts"
@@ -31,7 +32,11 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string)
 		return
 	}
 
-	log.Printf("SendEntry: sending %q from %q for %q", params.Entry, params.Archive, r.URL.Path)
+	log.WithFields(log.Fields{
+		"entry":   params.Entry,
+		"archive": params.Archive,
+		"path":    r.URL.Path,
+	}).Print("SendEntry: sending")
 
 	if params.Archive == "" || params.Entry == "" {
 		helper.Fail500(w, r, fmt.Errorf("SendEntry: Archive or Entry is empty"))

internal/git/blob.go

@@ -3,10 +3,11 @@ package git
 import (
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"strings"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
@@ -50,7 +51,10 @@ func handleSendBlobWithGitaly(w http.ResponseWriter, r *http.Request, params *bl
 }
 
 func handleSendBlobLocally(w http.ResponseWriter, r *http.Request, params *blobParams) {
-	log.Printf("SendBlob: sending %q for %q", params.BlobId, r.URL.Path)
+	log.WithFields(log.Fields{
+		"blobId": params.BlobId,
+		"path":   r.URL.Path,
+	}).Print("SendBlob: sending")
 
 	sizeOutput, err := gitCommand("git", "--git-dir="+params.RepoPath, "cat-file", "-s", params.BlobId).Output()
 	if err != nil {

internal/git/diff.go

@@ -3,9 +3,10 @@ package git
 import (
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
@@ -60,7 +61,11 @@ func handleSendDiffWithGitaly(w http.ResponseWriter, r *http.Request, params *di
 }
 
 func handleSendDiffLocally(w http.ResponseWriter, r *http.Request, params *diffParams) {
-	log.Printf("SendDiff: sending diff between %q and %q for %q", params.ShaFrom, params.ShaTo, r.URL.Path)
+	log.WithFields(log.Fields{
+		"shaFrom": params.ShaFrom,
+		"shaTo":   params.ShaTo,
+		"path":    r.URL.Path,
+	}).Print("SendDiff: sending diff")
 
 	gitDiffCmd := gitCommand("git", "--git-dir="+params.RepoPath, "diff", params.ShaFrom, params.ShaTo)
 	stdout, err := gitDiffCmd.StdoutPipe()

internal/git/format-patch.go

@@ -3,9 +3,10 @@ package git
 import (
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
@@ -59,7 +60,11 @@ func handleSendPatchWithGitaly(w http.ResponseWriter, r *http.Request, params *p
 }
 
 func handleSendPatchLocally(w http.ResponseWriter, r *http.Request, params *patchParams) {
-	log.Printf("SendPatch: sending patch between %q and %q for %q", params.ShaFrom, params.ShaTo, r.URL.Path)
+	log.WithFields(log.Fields{
+		"shaFrom": params.ShaFrom,
+		"shaTo":   params.ShaTo,
+		"path":    r.URL.Path,
+	}).Print("SendPatch: sending patch")
 
 	gitRange := fmt.Sprintf("%s..%s", params.ShaFrom, params.ShaTo)
 	gitPatchCmd := gitCommand("git", "--git-dir="+params.RepoPath, "format-patch", gitRange, "--stdout")

internal/helper/accesslogformatter.go

+package helper
+
+import (
+	"bytes"
+	"fmt"
+
+	log "github.com/sirupsen/logrus"
+)
+
+func forNil(v interface{}, otherwise interface{}) interface{} {
+	if v == nil {
+		return otherwise
+	}
+
+	return v
+}
+
+// accessLogFormatter formats logs into a format similar to the combined access log format
+// See https://httpd.apache.org/docs/1.3/logs.html#combined
+type accessLogFormatter struct {
+	clock Clock
+}
+
+// Format renders a single log entry
+func (f *accessLogFormatter) Format(entry *log.Entry) ([]byte, error) {
+	host := forNil(entry.Data["host"], "-")
+	remoteAddr := forNil(entry.Data["remoteAddr"], "")
+	method := forNil(entry.Data["method"], "")
+	uri := forNil(entry.Data["uri"], "")
+	proto := forNil(entry.Data["proto"], "")
+	status := forNil(entry.Data["status"], 0)
+	written := forNil(entry.Data["written"], 0)
+	referer := forNil(entry.Data["referer"], "")
+	userAgent := forNil(entry.Data["userAgent"], "")
+	duration := forNil(entry.Data["duration"], 0.0)
+
+	now := f.clock.Now().Format("2006/01/02:15:04:05 -0700")
+
+	requestLine := fmt.Sprintf("%s %s %s", method, uri, proto)
+
+	buf := &bytes.Buffer{}
+	_, err := fmt.Fprintf(buf, "%s %s - - [%s] %q %d %d %q %q %.3f\n",
+		host, remoteAddr, now, requestLine,
+		status, written, referer, userAgent, duration,
+	)
+
+	return buf.Bytes(), err
+}
+
+// NewAccessLogFormatter returns a new formatter for combined access logs
+func NewAccessLogFormatter() log.Formatter {
+	return &accessLogFormatter{clock: &RealClock{}}
+}

internal/helper/accesslogformatter_test.go

+package helper
+
+import (
+	"io/ioutil"
+	"testing"
+	"time"
+
+	log "github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestAccessLogFormatter_Format(t *testing.T) {
+	discardLogger := log.New()
+	discardLogger.Out = ioutil.Discard
+
+	tests := []struct {
+		name  string
+		entry *log.Entry
+		want  string
+	}{
+		{
+			"blank",
+			discardLogger.WithField("blank", ""),
+			"-  - - [2018/01/07:00:00:00 +0000] \"  \" 0 0 \"\" \"\" 0.000\n",
+		},
+		{
+			"full",
+			discardLogger.WithFields(log.Fields{
+				"host":       "gitlab.com",
+				"remoteAddr": "127.0.0.1",
+				"method":     "GET",
+				"uri":        "/",
+				"proto":      "HTTP/1.1",
+				"status":     200,
+				"written":    100,
+				"referer":    "http://localhost",
+				"userAgent":  "Mozilla/1.0",
+				"duration":   5.0,
+			}),
+			"gitlab.com 127.0.0.1 - - [2018/01/07:00:00:00 +0000] \"GET / HTTP/1.1\" 200 100 \"http://localhost\" \"Mozilla/1.0\" 5.000\n",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			f := &accessLogFormatter{clock: &StubClock{time.Unix(1515283200, 0)}}
+
+			got, err := f.Format(tt.entry)
+			if err != nil {
+				t.Errorf("AccessLogFormatter.Format() error = %v", err)
+				return
+			}
+
+			assert.Equal(t, tt.want, string(got))
+		})
+	}
+}

internal/helper/clock.go

+package helper
+
+import (
+	"time"
+)
+
+// Clock interface provides the time
+type Clock interface {
+	Now() time.Time
+}
+
+// RealClock is the default time implementation
+type RealClock struct{}
+
+// Now returns the time
+func (RealClock) Now() time.Time { return time.Now() }
+
+// StubClock is the default time implementation
+type StubClock struct {
+	StubTime time.Time
+}
+
+// Now returns a stub time
+func (c *StubClock) Now() time.Time { return c.StubTime }

internal/helper/helpers.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"errors"
 	"io/ioutil"
-	"log"
 	"mime"
 	"net"
 	"net/http"
@@ -14,6 +13,8 @@ import (
 	"regexp"
 	"strings"
 	"syscall"
+
+	log "github.com/sirupsen/logrus"
 )
 
 const NginxResponseBufferHeader = "X-Accel-Buffering"
@@ -45,9 +46,12 @@ func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
 
 func printError(r *http.Request, err error) {
 	if r != nil {
-		log.Printf("error: %s %q: %v", r.Method, ScrubURLParams(r.RequestURI), err)
+		log.WithFields(log.Fields{
+			"method": r.Method,
+			"uri":    ScrubURLParams(r.RequestURI),
+		}).WithError(err).Error("error")
 	} else {
-		log.Printf("error: %v", err)
+		log.WithError(err).Error("unknown error")
 	}
 }
 
@@ -90,7 +94,7 @@ func OpenFile(path string) (file *os.File, fi os.FileInfo, err error) {
 func URLMustParse(s string) *url.URL {
 	u, err := url.Parse(s)
 	if err != nil {
-		log.Fatalf("urlMustParse: %q %v", s, err)
+		log.WithField("url", s).WithError(err).Fatal("urlMustParse")
 	}
 	return u
 }

internal/helper/logging.go

@@ -2,20 +2,17 @@ package helper
 
 import (
 	"bufio"
-	"fmt"
-	"io"
-	"log"
 	"net"
 	"net/http"
-	"os"
 	"strconv"
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
+	log "github.com/sirupsen/logrus"
 )
 
 var (
-	responseLogger *log.Logger
+	accessLogEntry *log.Entry
 
 	sessionsActive = prometheus.NewGauge(prometheus.GaugeOpts{
 		Name: "gitlab_workhorse_http_sessions_active",
@@ -32,12 +29,12 @@ var (
 )
 
 func init() {
-	SetCustomResponseLogger(os.Stderr)
 	registerPrometheusMetrics()
 }
 
-func SetCustomResponseLogger(writer io.Writer) {
-	responseLogger = log.New(writer, "", 0)
+// SetAccessLoggerEntry sets the access logger used in the system
+func SetAccessLoggerEntry(logEntry *log.Entry) {
+	accessLogEntry = logEntry
 }
 
 func registerPrometheusMetrics() {
@@ -48,23 +45,24 @@ func registerPrometheusMetrics() {
 type LoggingResponseWriter interface {
 	http.ResponseWriter
 
-	Log(r *http.Request)
+	RequestFinished(r *http.Request)
 }
 
-type loggingResponseWriter struct {
-	rw      http.ResponseWriter
-	status  int
-	written int64
-	started time.Time
+type statsCollectingResponseWriter struct {
+	rw          http.ResponseWriter
+	status      int
+	wroteHeader bool
+	written     int64
+	started     time.Time
 }
 
 type hijackingResponseWriter struct {
-	loggingResponseWriter
+	statsCollectingResponseWriter
 }
 
-func NewLoggingResponseWriter(rw http.ResponseWriter) LoggingResponseWriter {
+func NewStatsCollectingResponseWriter(rw http.ResponseWriter) LoggingResponseWriter {
 	sessionsActive.Inc()
-	out := loggingResponseWriter{
+	out := statsCollectingResponseWriter{
 		rw:      rw,
 		started: time.Now(),
 	}
@@ -77,41 +75,63 @@ func NewLoggingResponseWriter(rw http.ResponseWriter) LoggingResponseWriter {
 }
 
 func (l *hijackingResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
-	// The only way to gethere is through NewLoggingResponseWriter(), which
+	// The only way to get here is through NewStatsCollectingResponseWriter(), which
 	// checks that this cast will be valid.
 	hijacker := l.rw.(http.Hijacker)
 	return hijacker.Hijack()
 }
 
-func (l *loggingResponseWriter) Header() http.Header {
+func (l *statsCollectingResponseWriter) Header() http.Header {
 	return l.rw.Header()
 }
 
-func (l *loggingResponseWriter) Write(data []byte) (n int, err error) {
-	if l.status == 0 {
+func (l *statsCollectingResponseWriter) Write(data []byte) (n int, err error) {
+	if !l.wroteHeader {
 		l.WriteHeader(http.StatusOK)
 	}
 	n, err = l.rw.Write(data)
+
 	l.written += int64(n)
 	return n, err
 }
 
-func (l *loggingResponseWriter) WriteHeader(status int) {
-	if l.status != 0 {
+func (l *statsCollectingResponseWriter) WriteHeader(status int) {
+	if l.wroteHeader {
 		return
 	}
-
+	l.wroteHeader = true
 	l.status = status
+
 	l.rw.WriteHeader(status)
 }
 
-func (l *loggingResponseWriter) Log(r *http.Request) {
+func (l *statsCollectingResponseWriter) writeAccessLog(r *http.Request) {
+	if accessLogEntry == nil {
+		return
+	}
+
+	accessLogEntry.WithFields(l.accessLogFields(r)).Info("access")
+}
+
+func (l *statsCollectingResponseWriter) accessLogFields(r *http.Request) log.Fields {
 	duration := time.Since(l.started)
-	responseLogger.Printf("%s %s - - [%s] %q %d %d %q %q %f\n",
-		r.Host, r.RemoteAddr, l.started,
-		fmt.Sprintf("%s %s %s", r.Method, ScrubURLParams(r.RequestURI), r.Proto),
-		l.status, l.written, ScrubURLParams(r.Referer()), r.UserAgent(), duration.Seconds(),
-	)
+
+	return log.Fields{
+		"host":       r.Host,
+		"remoteAddr": r.RemoteAddr,
+		"method":     r.Method,
+		"uri":        ScrubURLParams(r.RequestURI),
+		"proto":      r.Proto,
+		"status":     l.status,
+		"written":    l.written,
+		"referer":    ScrubURLParams(r.Referer()),
+		"userAgent":  r.UserAgent(),
+		"duration":   duration.Seconds(),
+	}
+}
+
+func (l *statsCollectingResponseWriter) RequestFinished(r *http.Request) {
+	l.writeAccessLog(r)
 
 	sessionsActive.Dec()
 	requestsTotal.WithLabelValues(strconv.Itoa(l.status), r.Method).Inc()

internal/helper/logging_test.go

+package helper
+
+import (
+	"fmt"
+	"net/http"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func Test_statsCollectingResponseWriter_accessLogFields(t *testing.T) {
+	passwords := []string{
+		"should_be_filtered",        // Basic case
+		"should+++filtered",         // Password contains  +
+		"this/is/a/to--ken",         // Password contains on / and -
+		"%E9%A9%AE%E9%A9%AC",        // Password contains URI Encoded chars
+		"should_be_%252E%252E%252F", // Password is mixed
+	}
+
+	queryStrings := []string{
+		"private-token=%s",
+		"authenticity-token=%s",
+		"rss-token=%s",
+		"private_token=%s",
+		"authenticity_token=%s",
+		"rss-token=%s",
+		"private-token=%s&authenticity-token=%s",
+		"private_token=%s&authenticity_token=%s",
+		"param=not_private&private-token=%s", // Non-private fields prefixed
+		"private-token=%s&param=not_private", // Non-private fields suffixed
+	}
+
+	paths := []string{
+		"",
+		"/",
+		"/groups/private_token/",
+	}
+
+	for i, password := range passwords {
+		for j, path := range paths {
+			for k, qs := range queryStrings {
+				queryString := strings.Replace(qs, "%s", password, -1)
+				t.Run(fmt.Sprintf("Test #%v %v %v", i, j, k), func(t *testing.T) {
+					resource := path + "?" + queryString
+
+					// Ensure the Referer is scrubbed too
+					req, err := http.NewRequest("GET", "/blah"+resource, nil)
+					assert.NoError(t, err, "GET %q: %v", resource, err)
+
+					req.Header.Set("Referer", "http://referer.example.com"+resource)
+					req.RequestURI = resource
+
+					l := &statsCollectingResponseWriter{
+						rw:          nil,
+						status:      200,
+						wroteHeader: true,
+						written:     50,
+						started:     time.Now(),
+					}
+
+					fields := l.accessLogFields(req)
+
+					uri := fields["uri"].(string)
+					assert.NotEmpty(t, uri, "uri is empty")
+					assert.Contains(t, uri, path, "GET %q: path not logged", resource)
+					assert.NotContains(t, uri, password, "GET %q: log not filtered correctly", resource)
+
+					referer := fields["referer"].(string)
+					assert.NotEmpty(t, referer, "referer is empty")
+					assert.Contains(t, referer, path, "GET %q: path not logged", resource)
+					assert.NotContains(t, referer, password, "GET %q: log not filtered correctly", resource)
+
+					assert.NotContains(t, fmt.Sprintf("%#v", fields), password, "password leaked into fields", fields)
+
+					if strings.Contains(queryString, "param=not_private") {
+						assert.Contains(t, uri, "param=not_private", "Missing non-private parameters in uri", uri)
+						assert.Contains(t, referer, "param=not_private", "Missing non-private parameters in referer", referer)
+					}
+				})
+
+			}
+		}
+	}
+
+}

internal/redis/keywatcher.go

@@ -2,11 +2,12 @@ package redis
 
 import (
 	"fmt"
-	"log"
 	"strings"
 	"sync"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 
 	"github.com/garyburd/redigo/redis"

internal/redis/redis.go

@@ -3,11 +3,12 @@ package redis
 import (
 	"errors"
 	"fmt"
-	"log"
 	"net"
 	"net/url"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
 
 	sentinel "github.com/FZambia/go-sentinel"
@@ -74,7 +75,9 @@ func sentinelConn(master string, urls []config.TomlURL) *sentinel.Sentinel {
 	var addrs []string
 	for _, url := range urls {
 		h := url.URL.Host
-		log.Printf("redis: using sentinel %q", h)
+		log.WithFields(log.Fields{
+			"host": h,
+		}).Printf("redis: using sentinel")
 		addrs = append(addrs, h)
 	}
 	return &sentinel.Sentinel{
@@ -180,7 +183,11 @@ func defaultDialer(dopts []redis.DialOption, keepAlivePeriod time.Duration, url
 }
 
 func redisDial(network, address string, options ...redis.DialOption) (redis.Conn, error) {
-	log.Printf("redis: dialing %q, %q", network, address)
+	log.WithFields(log.Fields{
+		"network": network,
+		"address": address,
+	}).Printf("redis: dialing")
+
 	return redis.Dial(network, address, options...)
 }
 

internal/sendfile/sendfile.go

@@ -7,10 +7,11 @@ via the X-Sendfile mechanism. All that is needed in the Rails code is the
 package sendfile
 
 import (
-	"log"
 	"net/http"
 	"regexp"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/prometheus/client_golang/prometheus"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
@@ -104,7 +105,12 @@ func (s *sendFileResponseWriter) WriteHeader(status int) {
 }
 
 func sendFileFromDisk(w http.ResponseWriter, r *http.Request, file string) {
-	log.Printf("Send file %q for %s %q", file, r.Method, helper.ScrubURLParams(r.RequestURI))
+	log.WithFields(log.Fields{
+		"file":   file,
+		"method": r.Method,
+		"uri":    helper.ScrubURLParams(r.RequestURI),
+	}).Print("Send file")
+
 	content, fi, err := helper.OpenFile(file)
 	if err != nil {
 		http.NotFound(w, r)

internal/sendurl/sendurl.go

@@ -3,11 +3,12 @@ package sendurl
 import (
 	"fmt"
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/prometheus/client_golang/prometheus"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
@@ -97,7 +98,10 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string)
 		return
 	}
 
-	log.Printf("SendURL: sending %q for %q", helper.ScrubURLParams(params.URL), r.URL.Path)
+	log.WithFields(log.Fields{
+		"url":  helper.ScrubURLParams(params.URL),
+		"path": r.URL.Path,
+	}).Print("SendURL: sending")
 
 	if params.URL == "" {
 		sendURLRequestsInvalidData.Inc()

internal/staticpages/servefile.go

 package staticpages
 
 import (
-	"log"
 	"net/http"
 	"os"
 	"path/filepath"
 	"strings"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/urlprefix"
 )
@@ -70,7 +71,12 @@ func (s *Static) ServeExisting(prefix urlprefix.Prefix, cache CacheMode, notFoun
 			w.Header().Set("Expires", cacheUntil)
 		}
 
-		log.Printf("Send static file %q (%q) for %s %q", file, w.Header().Get("Content-Encoding"), r.Method, helper.ScrubURLParams(r.RequestURI))
+		log.WithFields(log.Fields{
+			"file":     file,
+			"encoding": w.Header().Get("Content-Encoding"),
+			"method":   r.Method,
+			"uri":      helper.ScrubURLParams(r.RequestURI),
+		}).Printf("Send static file")
 		http.ServeContent(w, r, filepath.Base(file), fi.ModTime(), content)
 	})
 }

internal/terminal/terminal.go

@@ -3,10 +3,11 @@ package terminal
 import (
 	"errors"
 	"fmt"
-	"log"
 	"net/http"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/gorilla/websocket"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/api"
@@ -46,7 +47,7 @@ func ProxyTerminal(w http.ResponseWriter, r *http.Request, terminal *api.Termina
 	server, err := connectToServer(terminal, r)
 	if err != nil {
 		helper.Fail500(w, r, err)
-		log.Printf("Terminal: connecting to server failed: %s", err)
+		log.WithError(err).Print("Terminal: connecting to server failed")
 		return
 	}
 	defer server.UnderlyingConn().Close()
@@ -54,7 +55,7 @@ func ProxyTerminal(w http.ResponseWriter, r *http.Request, terminal *api.Termina
 
 	client, err := upgradeClient(w, r)
 	if err != nil {
-		log.Printf("Terminal: upgrading client to websocket failed: %s", err)
+		log.WithError(err).Print("Terminal: upgrading client to websocket failed")
 		return
 	}
 
@@ -65,11 +66,17 @@ func ProxyTerminal(w http.ResponseWriter, r *http.Request, terminal *api.Termina
 	defer client.UnderlyingConn().Close()
 	clientAddr := getClientAddr(r) // We can't know the port with confidence
 
-	log.Printf("Terminal: started proxying from %s to %s", clientAddr, serverAddr)
-	defer log.Printf("Terminal: finished proxying from %s to %s", clientAddr, serverAddr)
+	logEntry := log.WithFields(log.Fields{
+		"clientAddr": clientAddr,
+		"serverAddr": serverAddr,
+	})
+
+	logEntry.Print("Terminal: started proxying")
+
+	defer logEntry.Print("Terminal: finished proxying")
 
 	if err := proxy.Serve(server, client, serverAddr, clientAddr); err != nil {
-		log.Printf("Terminal: error proxying from %s to %s: %s", clientAddr, serverAddr, err)
+		logEntry.WithError(err).Print("Terminal: error proxying")
 	}
 }
 

internal/testhelper/gitaly.go

@@ -4,11 +4,12 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"path"
 	"strings"
 	"sync"
 
+	log "github.com/sirupsen/logrus"
+
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
 
 	"golang.org/x/net/context"

internal/testhelper/testhelper.go

@@ -6,7 +6,6 @@ import (
 	"errors"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -17,6 +16,8 @@ import (
 	"strings"
 	"testing"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/secret"
 )
 

internal/upstream/upstream.go

@@ -54,8 +54,8 @@ func (u *Upstream) configureURLPrefix() {
 }
 
 func (u *Upstream) ServeHTTP(ow http.ResponseWriter, r *http.Request) {
-	w := helper.NewLoggingResponseWriter(ow)
-	defer w.Log(r)
+	w := helper.NewStatsCollectingResponseWriter(ow)
+	defer w.RequestFinished(r)
 
 	helper.DisableResponseBuffering(w)
 

logging.go

 package main
 
 import (
-	"log"
+	"io"
+	"io/ioutil"
+	goLog "log"
 	"os"
 	"os/signal"
 	"syscall"
 
-	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
-
 	"github.com/client9/reopen"
+	log "github.com/sirupsen/logrus"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 )
 
 func reopenLogWriter(l reopen.WriteCloser, sighup chan os.Signal) {
 	for _ = range sighup {
-		log.Printf("Reopening log file")
+		log.Print("Reopening log file")
 		l.Reopen()
 	}
 }
 
-func startLogging(logFile string) {
-	var logWriter = reopen.Stderr
-
-	if logFile != "" {
-		file, err := reopen.NewFileWriter(logFile)
-		if err != nil {
-			log.Fatalf("Unable to set output log: %s", err)
-		}
-		logWriter = file
+func prepareLoggingFile(logFile string) *reopen.FileWriter {
+	file, err := reopen.NewFileWriter(logFile)
+	if err != nil {
+		goLog.Fatalf("Unable to set output log: %s", err)
 	}
 
-	log.SetOutput(logWriter)
-	helper.SetCustomResponseLogger(logWriter)
-
 	sighup := make(chan os.Signal, 1)
 	signal.Notify(sighup, syscall.SIGHUP)
 
-	go reopenLogWriter(logWriter, sighup)
+	go reopenLogWriter(file, sighup)
+	return file
+}
+
+const (
+	jsonLogFormat = "json"
+	textLogFormat = "text"
+	noneLogType   = "none"
+)
+
+type logConfiguration struct {
+	logFile   string
+	logFormat string
+}
+
+func startLogging(config logConfiguration) {
+	var accessLogEntry *log.Entry
+	var logOutputWriter io.Writer
+
+	if config.logFile != "" {
+		logOutputWriter = prepareLoggingFile(config.logFile)
+	} else {
+		logOutputWriter = os.Stderr
+	}
+
+	switch config.logFormat {
+	case noneLogType:
+		accessLogEntry = nil
+		logOutputWriter = ioutil.Discard
+	case jsonLogFormat:
+		accessLogEntry = log.WithField("system", "http")
+		log.SetFormatter(&log.JSONFormatter{})
+	case textLogFormat:
+		accessLogger := log.New()
+		accessLogger.Formatter = helper.NewAccessLogFormatter()
+		accessLogger.Out = logOutputWriter
+		accessLogger.SetLevel(log.InfoLevel)
+		accessLogEntry = accessLogger.WithField("system", "http")
+
+		log.SetFormatter(&log.TextFormatter{})
+	default:
+		log.WithField("logFormat", config.logFormat).Fatal("Unknown logFormat configured")
+	}
+
+	helper.SetAccessLoggerEntry(accessLogEntry)
+	log.SetOutput(logOutputWriter)
+
+	// Golog always goes to stderr
+	goLog.SetOutput(os.Stderr)
+
 }

main.go

@@ -16,7 +16,6 @@ package main
 import (
 	"flag"
 	"fmt"
-	"log"
 	"net"
 	"net/http"
 	_ "net/http/pprof"
@@ -24,6 +23,8 @@ import (
 	"syscall"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/queueing"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/redis"
@@ -52,9 +53,16 @@ var apiLimit = flag.Uint("apiLimit", 0, "Number of API requests allowed at singl
 var apiQueueLimit = flag.Uint("apiQueueLimit", 0, "Number of API requests allowed to be queued")
 var apiQueueTimeout = flag.Duration("apiQueueDuration", queueing.DefaultTimeout, "Maximum queueing duration of requests")
 var apiCiLongPollingDuration = flag.Duration("apiCiLongPollingDuration", 50, "Long polling duration for job requesting for runners (default 50s - enabled)")
-var logFile = flag.String("logFile", "", "Log file to be used")
+
 var prometheusListenAddr = flag.String("prometheusListenAddr", "", "Prometheus listening address, e.g. 'localhost:9229'")
 
+var logConfig = logConfiguration{}
+
+func init() {
+	flag.StringVar(&logConfig.logFile, "logFile", "", "Log file location")
+	flag.StringVar(&logConfig.logFormat, "logFormat", "text", "Log format to use defaults to text (text, json, none)")
+}
+
 func main() {
 	flag.Usage = func() {
 		fmt.Fprintf(os.Stderr, "Usage of %s:\n", os.Args[0])
@@ -69,14 +77,14 @@ func main() {
 		os.Exit(0)
 	}
 
-	startLogging(*logFile)
+	startLogging(logConfig)
 
 	backendURL, err := parseAuthBackend(*authBackend)
 	if err != nil {
-		log.Fatalf("invalid authBackend: %v", err)
+		log.WithError(err).Fatal("invalid authBackend")
 	}
 
-	log.Printf("Starting %s", version)
+	log.WithField("version", version).Print("Starting")
 
 	// Good housekeeping for Unix sockets: unlink before binding
 	if *listenNetwork == "unix" {
@@ -128,7 +136,7 @@ func main() {
 	if *configFile != "" {
 		cfgFromFile, err := config.LoadConfig(*configFile)
 		if err != nil {
-			log.Fatalf("Can not load config file %q: %v", *configFile, err)
+			log.WithField("configFile", *configFile).WithError(err).Fatal("Can not load config file")
 		}
 
 		cfg.Redis = cfgFromFile.Redis

main_test.go

@@ -7,7 +7,6 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -18,6 +17,8 @@ import (
 	"testing"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/api"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/git"
@@ -52,14 +53,14 @@ func TestMain(m *testing.M) {
 		testCmd.Stderr = os.Stderr
 
 		if err := testCmd.Run(); err != nil {
-			log.Printf("Test setup: failed to run %v", testCmd)
+			log.WithField("testCmd", testCmd).Print("Test setup: failed to run")
 			os.Exit(-1)
 		}
 	}
 
 	cleanup, err := testhelper.BuildExecutables()
 	if err != nil {
-		log.Printf("Test setup: failed to build executables: %v", err)
+		log.WithError(err).Print("Test setup: failed to build executables")
 		os.Exit(1)
 	}
 
@@ -572,67 +573,6 @@ func TestAPIFalsePositivesAreProxied(t *testing.T) {
 	}
 }
 
-func TestQueryStringLogFiltering(t *testing.T) {
-	// capture the log output
-	buf := bytes.NewBuffer(nil)
-	log.SetOutput(buf)
-	helper.SetCustomResponseLogger(buf)
-
-	defer log.SetOutput(os.Stderr)
-	defer helper.SetCustomResponseLogger(os.Stderr)
-
-	ts := testhelper.TestServerWithHandler(regexp.MustCompile(`.`), func(w http.ResponseWriter, _ *http.Request) {
-		w.WriteHeader(200)
-	})
-	defer ts.Close()
-
-	ws := startWorkhorseServer(ts.URL)
-	defer ws.Close()
-
-	for _, path := range []string{
-		"",
-		"/",
-	} {
-		for _, queryString := range []string{
-			"private-token=should_be_filtered",
-			"authenticity-token=should_be_filtered",
-			"rss-token=should_be_filtered",
-			"private_token=should_be_filtered",
-			"authenticity_token=should_be_filtered",
-			"rss-token=should_be_filtered",
-			"private-token=should_be_filtered&authenticity-token=should_be_filtered",
-			"private_token=should_be_filtered&authenticity_token=should_be_filtered",
-		} {
-			resource := path + "?" + queryString
-
-			// Ensure the Referer is scrubbed too
-			req, err := http.NewRequest("GET", ws.URL+resource, nil)
-			if !assert.NoError(t, err, "GET %q: %v", resource, err) {
-				continue
-			}
-
-			req.Header.Set("Referer", "http://referer.example.com"+resource)
-
-			resp, err := http.DefaultClient.Do(req)
-			if !assert.NoError(t, err, "GET %q: %v", resource, err) {
-				continue
-			}
-
-			resp.Body.Close()
-
-			assert.Equal(t, 200, resp.StatusCode, "GET %q: status code", resource)
-
-			logged := buf.String()
-			buf.Reset()
-
-			assert.NotEqual(t, 0, len(logged), "GET %q: log is empty", resource)
-			assert.Contains(t, logged, path, "GET %q: path not logged", resource)
-			assert.Contains(t, logged, "referer", "GET %q: referer not logged", resource)
-			assert.NotContains(t, logged, "should_be_filtered", "GET %q: log not filtered correctly", resource)
-		}
-	}
-}
-
 func setupStaticFile(fpath, content string) error {
 	cwd, err := os.Getwd()
 	if err != nil {

sendfile_test.go

@@ -4,13 +4,14 @@ import (
 	"bytes"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"net/http/httptest"
 	"os"
 	"os/exec"
 	"path"
 	"testing"
+
+	log "github.com/sirupsen/logrus"
 )
 
 func TestDeniedLfsDownload(t *testing.T) {

terminal_test.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"encoding/pem"
 	"fmt"
-	"log"
 	"net"
 	"net/http"
 	"net/http/httptest"
@@ -14,6 +13,8 @@ import (
 	"testing"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/gorilla/websocket"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/api"
@@ -67,7 +68,7 @@ func TestTerminalBadTLS(t *testing.T) {
 		t.Fatalf("Expected connection to fail ErrBadHandshake, got: %v", err)
 	}
 	if err == nil {
-		log.Println("TLS negotiation should have failed!")
+		log.Info("TLS negotiation should have failed!")
 		defer client.Close()
 	}
 }