Merge branch 'mk-bump-workhorse' into 'master'

Bump workhorse to 8.59.0

See merge request gitlab-org/gitlab!51329

GITLAB_WORKHORSE_VERSION

-8.58.2
+8.59.0

changelogs/unreleased/mk-bump-workhorse.yml

+---
+title: Bump workhorse to 8.59.0
+merge_request: 51329
+author:
+type: changed

workhorse/.gitlab-ci.yml

@@ -49,6 +49,10 @@ test using go 1.14:
   extends: .test
   image: golang:1.14
 
+test using go 1.15:
+  extends: .test
+  image: golang:1.15
+
 test:release:
   rules:
     - if: '$CI_COMMIT_TAG'

workhorse/CHANGELOG

 # Changelog for gitlab-workhorse
 
-## v8.58.2
+## v8.59.0
 
-### Security
-- Allow DELETE HTTP method
-  https://gitlab.com/gitlab-org/gitlab-workhorse/-/merge_requests/
+### Fixed
+- Image scaling: strip out iCCP chunks in PNG files
+  https://gitlab.com/gitlab-org/gitlab-workhorse/-/merge_requests/673
 
-## v8.58.1
+### Other
+- Extract logging concerns into a separate module
+  https://gitlab.com/gitlab-org/gitlab-workhorse/-/merge_requests/
 
 ### Security
 - Reject unknown http methods

workhorse/Makefile

@@ -22,8 +22,6 @@ export PATH := $(GOBIN):$(PATH)
 export GOPROXY ?= https://proxy.golang.org
 export GO111MODULE=on
 
-LOCAL_GO_FILES = $(shell find . -type f -name '*.go' | grep -v -e /_ -e /testdata/ -e '^\./\.')
-
 define message
 	@echo "### $(1)"
 endef
@@ -40,19 +38,23 @@ $(TARGET_SETUP):
 	mkdir -p "$(TARGET_DIR)"
 	touch "$(TARGET_SETUP)"
 
-gitlab-resize-image: $(TARGET_SETUP) $(shell find cmd/gitlab-resize-image/ -name '*.go')
+.PHONY: gitlab-resize-image
+gitlab-resize-image: $(TARGET_SETUP)
 	$(call message,Building $@)
 	$(GOBUILD) -tags "$(BUILD_TAGS)" -o $(BUILD_DIR)/$@ $(PKG)/cmd/$@
 
-gitlab-zip-cat:	$(TARGET_SETUP) $(shell find cmd/gitlab-zip-cat/ -name '*.go')
+.PHONY: gitlab-zip-cat
+gitlab-zip-cat: $(TARGET_SETUP)
 	$(call message,Building $@)
 	$(GOBUILD) -tags "$(BUILD_TAGS)" -o $(BUILD_DIR)/$@ $(PKG)/cmd/$@
 
-gitlab-zip-metadata:	$(TARGET_SETUP) $(shell find cmd/gitlab-zip-metadata/ -name '*.go')
+.PHONY: gitlab-zip-metadata
+gitlab-zip-metadata: $(TARGET_SETUP)
 	$(call message,Building $@)
 	$(GOBUILD) -tags "$(BUILD_TAGS)" -o $(BUILD_DIR)/$@ $(PKG)/cmd/$@
 
-gitlab-workhorse:	$(TARGET_SETUP) $(shell find . -name '*.go' | grep -v '^\./_')
+.PHONY: gitlab-workhorse
+gitlab-workhorse: $(TARGET_SETUP)
 	$(call message,Building $@)
 	$(GOBUILD) -tags "$(BUILD_TAGS)" -o $(BUILD_DIR)/$@ $(PKG)
 
@@ -142,7 +144,7 @@ detect-assert:
 .PHONY: check-formatting
 check-formatting: $(TARGET_SETUP) install-goimports
 	$(call message,Verify: $@)
-	@_support/validate-formatting.sh $(LOCAL_GO_FILES)
+	@_support/fmt.sh check
 
 # Megacheck will tailor some responses given a minimum Go version, so pass that through the CLI
 # Additionally, megacheck will not return failure exit codes unless explicitly told to via the
@@ -158,7 +160,7 @@ staticcheck: $(TARGET_SETUP)
 .PHONY: fmt
 fmt: $(TARGET_SETUP) install-goimports
 	$(call message,$@)
-	@goimports -w -local $(PKG) -l $(LOCAL_GO_FILES)
+	@_support/fmt.sh
 
 .PHONY:	goimports
 install-goimports:	$(TARGET_SETUP)

workhorse/PROCESS.md

@@ -42,6 +42,7 @@ maintainers. The release process is:
 -   the new version will only be deployed to `gitlab.com` if [`GITLAB_WORKHORSE_VERSION`](https://gitlab.com/gitlab-org/gitlab/-/blob/master/GITLAB_WORKHORSE_VERSION) is updated accordingly;
     if applicable, please remind the person who originally asked for a new release to make this change
     (the MR should include a link back to the [version tag](https://gitlab.com/gitlab-org/gitlab-workhorse/-/tags) and a copy of the changelog)
+-   the person who updates GITLAB_WORKHORSE_VERSION should also run `scripts/update-workhorse` after commiting the new GITLAB_WORKHORSE_VERSION. If they forget they will be reminded by CI.
 
 ## Security releases
 

workhorse/VERSION

-8.58.2
+8.59.0

workhorse/_support/fmt.sh

+#!/bin/sh
+
+FLAG=-w
+if [ "x$1" = xcheck ]; then
+  FLAG=-e
+fi
+
+IMPORT_RESULT=$(
+  goimports $FLAG -local "gitlab.com/gitlab-org/gitlab-workhorse" -l $(
+    find . -type f -name '*.go' | grep -v -e /_ -e /testdata/ -e '^\./\.'
+  )
+)
+
+case "x$1" in
+  xcheck)
+    if [ -n "${IMPORT_RESULT}" ]; then
+      echo >&2 "Formatting or imports need fixing: 'make fmt'"
+      echo "${IMPORT_RESULT}"
+      exit 1
+    fi
+    ;;
+  x)
+    echo "${IMPORT_RESULT}"
+    ;;
+esac

workhorse/_support/validate-formatting.sh

-#!/bin/sh
-
-IMPORT_RESULT=$(goimports -e -local "gitlab.com/gitlab-org/gitlab-workhorse" -l "$@")
-
-if [ -n "${IMPORT_RESULT}" ]; then
-  echo >&2 "Formatting or imports need fixing: 'make fmt'"
-  echo "${IMPORT_RESULT}"
-  exit 1
-fi

workhorse/cmd/gitlab-resize-image/main.go

@@ -7,6 +7,8 @@ import (
 	"strconv"
 
 	"github.com/disintegration/imaging"
+
+	"gitlab.com/gitlab-org/gitlab-workhorse/cmd/gitlab-resize-image/png"
 )
 
 func main() {
@@ -23,7 +25,12 @@ func _main() error {
 		return fmt.Errorf("GL_RESIZE_IMAGE_WIDTH: %w", err)
 	}
 
-	src, formatName, err := image.Decode(os.Stdin)
+	pngReader, err := png.NewReader(os.Stdin)
+	if err != nil {
+		return fmt.Errorf("construct PNG reader: %w", err)
+	}
+
+	src, formatName, err := image.Decode(pngReader)
 	if err != nil {
 		return fmt.Errorf("decode: %w", err)
 	}

workhorse/cmd/gitlab-resize-image/png/reader.go

+package png
+
+import (
+	"bytes"
+	"encoding/binary"
+	"fmt"
+	"io"
+	"io/ioutil"
+	"os"
+)
+
+const (
+	pngMagicLen = 8
+	pngMagic    = "\x89PNG\r\n\x1a\n"
+)
+
+// Reader is an io.Reader decorator that skips certain PNG chunks known to cause problems.
+// If the image stream is not a PNG, it will yield all bytes unchanged to the underlying
+// reader.
+// See also https://gitlab.com/gitlab-org/gitlab/-/issues/287614
+type Reader struct {
+	underlying     io.Reader
+	chunk          io.Reader
+	bytesRemaining int64
+}
+
+func NewReader(r io.Reader) (io.Reader, error) {
+	magicBytes, err := readMagic(r)
+	if err != nil {
+		return nil, err
+	}
+
+	if string(magicBytes) != pngMagic {
+		debug("Not a PNG - read file unchanged")
+		return io.MultiReader(bytes.NewReader(magicBytes), r), nil
+	}
+
+	return io.MultiReader(bytes.NewReader(magicBytes), &Reader{underlying: r}), nil
+}
+
+func (r *Reader) Read(p []byte) (int, error) {
+	for r.bytesRemaining == 0 {
+		const (
+			headerLen = 8
+			crcLen    = 4
+		)
+		var header [headerLen]byte
+		_, err := io.ReadFull(r.underlying, header[:])
+		if err != nil {
+			return 0, err
+		}
+
+		chunkLen := int64(binary.BigEndian.Uint32(header[:4]))
+		if chunkType := string(header[4:]); chunkType == "iCCP" {
+			debug("!! iCCP chunk found; skipping")
+			if _, err := io.CopyN(ioutil.Discard, r.underlying, chunkLen+crcLen); err != nil {
+				return 0, err
+			}
+			continue
+		}
+
+		r.bytesRemaining = headerLen + chunkLen + crcLen
+		r.chunk = io.MultiReader(bytes.NewReader(header[:]), io.LimitReader(r.underlying, r.bytesRemaining-headerLen))
+	}
+
+	n, err := r.chunk.Read(p)
+	r.bytesRemaining -= int64(n)
+	return n, err
+}
+
+func debug(args ...interface{}) {
+	if os.Getenv("DEBUG") == "1" {
+		fmt.Fprintln(os.Stderr, args...)
+	}
+}
+
+// Consume PNG magic and proceed to reading the IHDR chunk.
+func readMagic(r io.Reader) ([]byte, error) {
+	var magicBytes []byte = make([]byte, pngMagicLen)
+	_, err := io.ReadFull(r, magicBytes)
+	if err != nil {
+		return nil, err
+	}
+
+	return magicBytes, nil
+}

workhorse/cmd/gitlab-resize-image/png/reader_test.go

+package png
+
+import (
+	"bytes"
+	"hash/crc64"
+	"image"
+	"io"
+	"io/ioutil"
+	"os"
+	"testing"
+
+	_ "image/jpeg" // registers JPEG format for image.Decode
+	"image/png"    // registers PNG format for image.Decode
+
+	"github.com/stretchr/testify/require"
+)
+
+const (
+	goodPNG     = "../../../testdata/image.png"
+	badPNG      = "../../../testdata/image_bad_iccp.png"
+	strippedPNG = "../../../testdata/image_stripped_iccp.png"
+	jpg         = "../../../testdata/image.jpg"
+)
+
+func TestReadImageUnchanged(t *testing.T) {
+	testCases := []struct {
+		desc      string
+		imagePath string
+		imageType string
+	}{
+		{
+			desc:      "image is not a PNG",
+			imagePath: jpg,
+			imageType: "jpeg",
+		},
+		{
+			desc:      "image is PNG without iCCP chunk",
+			imagePath: goodPNG,
+			imageType: "png",
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.desc, func(t *testing.T) {
+			requireValidImage(t, pngReader(t, tc.imagePath), tc.imageType)
+			requireStreamUnchanged(t, pngReader(t, tc.imagePath), rawImageReader(t, tc.imagePath))
+		})
+	}
+}
+
+func TestReadPNGWithBadICCPChunkDecodesAndReEncodesSuccessfully(t *testing.T) {
+	badPNGBytes, fmt, err := image.Decode(pngReader(t, badPNG))
+	require.NoError(t, err)
+	require.Equal(t, "png", fmt)
+
+	strippedPNGBytes, fmt, err := image.Decode(pngReader(t, strippedPNG))
+	require.NoError(t, err)
+	require.Equal(t, "png", fmt)
+
+	buf1 := new(bytes.Buffer)
+	buf2 := new(bytes.Buffer)
+
+	require.NoError(t, png.Encode(buf1, badPNGBytes))
+	require.NoError(t, png.Encode(buf2, strippedPNGBytes))
+
+	requireStreamUnchanged(t, buf1, buf2)
+}
+
+func pngReader(t *testing.T, path string) io.Reader {
+	r, err := NewReader(rawImageReader(t, path))
+	require.NoError(t, err)
+	return r
+}
+
+func rawImageReader(t *testing.T, path string) io.Reader {
+	f, err := os.Open(path)
+	require.NoError(t, err)
+	return f
+}
+
+func requireValidImage(t *testing.T, r io.Reader, expected string) {
+	_, fmt, err := image.Decode(r)
+	require.NoError(t, err)
+	require.Equal(t, expected, fmt)
+}
+
+func requireStreamUnchanged(t *testing.T, actual io.Reader, expected io.Reader) {
+	actualBytes, err := ioutil.ReadAll(actual)
+	require.NoError(t, err)
+	expectedBytes, err := ioutil.ReadAll(expected)
+	require.NoError(t, err)
+
+	table := crc64.MakeTable(crc64.ISO)
+	sumActual := crc64.Checksum(actualBytes, table)
+	sumExpected := crc64.Checksum(expectedBytes, table)
+	require.Equal(t, sumExpected, sumActual)
+}

workhorse/internal/api/api.go

@@ -18,6 +18,8 @@ import (
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/secret"
 )
 
@@ -322,7 +324,7 @@ func passResponseBack(httpResponse *http.Response, w http.ResponseWriter, r *htt
 	}
 	w.WriteHeader(httpResponse.StatusCode)
 	if _, err := io.Copy(w, responseBody); err != nil {
-		helper.LogError(r, err)
+		log.WithRequest(r).WithError(err).Error()
 	}
 }
 

workhorse/internal/badgateway/roundtripper.go

@@ -9,9 +9,7 @@ import (
 	"strings"
 	"time"
 
-	"gitlab.com/gitlab-org/labkit/log"
-
-	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 // Error is a custom error for pretty Sentry 'issues'
@@ -42,11 +40,7 @@ func (t *roundTripper) RoundTrip(r *http.Request) (*http.Response, error) {
 	// instead of 500s we catch the RoundTrip error here and inject a
 	// 502 response.
 	fields := log.Fields{"duration_ms": int64(time.Since(start).Seconds() * 1000)}
-	helper.LogErrorWithFields(
-		r,
-		&sentryError{fmt.Errorf("badgateway: failed to receive response: %v", err)},
-		fields,
-	)
+	log.WithRequest(r).WithFields(fields).WithError(&sentryError{fmt.Errorf("badgateway: failed to receive response: %v", err)}).Error()
 
 	injectedResponse := &http.Response{
 		StatusCode: http.StatusBadGateway,

workhorse/internal/git/archive.go

@@ -24,6 +24,7 @@ import (
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -116,14 +117,14 @@ func (a *archive) Inject(w http.ResponseWriter, r *http.Request, sendData string
 	setArchiveHeaders(w, format, archiveFilename)
 	w.WriteHeader(200) // Don't bother with HTTP 500 from this point on, just return
 	if _, err := io.Copy(w, reader); err != nil {
-		helper.LogError(r, &copyError{fmt.Errorf("SendArchive: copy 'git archive' output: %v", err)})
+		log.WithRequest(r).WithError(&copyError{fmt.Errorf("SendArchive: copy 'git archive' output: %v", err)}).Error()
 		return
 	}
 
 	if cacheEnabled {
 		err := finalizeCachedArchive(tempFile, params.ArchivePath)
 		if err != nil {
-			helper.LogError(r, fmt.Errorf("SendArchive: finalize cached archive: %v", err))
+			log.WithRequest(r).WithError(fmt.Errorf("SendArchive: finalize cached archive: %v", err)).Error()
 			return
 		}
 	}

workhorse/internal/git/diff.go

@@ -8,6 +8,7 @@ import (
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -39,10 +40,7 @@ func (d *diff) Inject(w http.ResponseWriter, r *http.Request, sendData string) {
 	}
 
 	if err := diffClient.SendRawDiff(ctx, w, request); err != nil {
-		helper.LogError(
-			r,
-			&copyError{fmt.Errorf("diff.RawDiff: request=%v, err=%v", request, err)},
-		)
+		log.WithRequest(r).WithError(&copyError{fmt.Errorf("diff.RawDiff: %v", err)}).Error()
 		return
 	}
 }

workhorse/internal/git/format-patch.go

@@ -8,6 +8,7 @@ import (
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -39,10 +40,7 @@ func (p *patch) Inject(w http.ResponseWriter, r *http.Request, sendData string)
 	}
 
 	if err := diffClient.SendRawPatch(ctx, w, request); err != nil {
-		helper.LogError(
-			r,
-			&copyError{fmt.Errorf("diff.RawPatch: request=%v, err=%v", request, err)},
-		)
+		log.WithRequest(r).WithError(&copyError{fmt.Errorf("diff.RawPatch: %v", err)}).Error()
 		return
 	}
 }

workhorse/internal/git/git-http.go

@@ -12,7 +12,7 @@ import (
 	"sync"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/api"
-	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 const (
@@ -54,7 +54,7 @@ func postRPCHandler(a *api.API, name string, handler func(*HttpResponseWriter, *
 			// no-op. It never reaches net/http because GitHttpResponseWriter calls
 			// WriteHeader on its underlying ResponseWriter at most once.
 			w.WriteHeader(500)
-			helper.LogError(r, fmt.Errorf("%s: %v", name, err))
+			log.WithRequest(r).WithError(fmt.Errorf("%s: %v", name, err)).Error()
 		}
 	})
 }

workhorse/internal/git/snapshot.go

@@ -9,6 +9,7 @@ import (
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -59,6 +60,6 @@ func (s *snapshot) Inject(w http.ResponseWriter, r *http.Request, sendData strin
 	w.WriteHeader(http.StatusOK) // Errors aren't detectable beyond this point
 
 	if _, err := io.Copy(w, reader); err != nil {
-		helper.LogError(r, fmt.Errorf("SendSnapshot: copy gitaly output: %v", err))
+		log.WithRequest(r).WithError(fmt.Errorf("SendSnapshot: copy gitaly output: %v", err)).Error()
 	}
 }

workhorse/internal/helper/helpers.go

@@ -20,13 +20,9 @@ import (
 
 const NginxResponseBufferHeader = "X-Accel-Buffering"
 
-func LogError(r *http.Request, err error) {
-	LogErrorWithFields(r, err, nil)
-}
-
-func LogErrorWithFields(r *http.Request, err error, fields log.Fields) {
+func logErrorWithFields(r *http.Request, err error, fields log.Fields) {
 	if err != nil {
-		captureRavenError(r, err, fields)
+		CaptureRavenError(r, err, fields)
 	}
 
 	printError(r, err, fields)
@@ -34,12 +30,7 @@ func LogErrorWithFields(r *http.Request, err error, fields log.Fields) {
 
 func CaptureAndFail(w http.ResponseWriter, r *http.Request, err error, msg string, code int) {
 	http.Error(w, msg, code)
-	LogError(r, err)
-}
-
-func CaptureAndFailWithFields(w http.ResponseWriter, r *http.Request, err error, msg string, code int, fields log.Fields) {
-	http.Error(w, msg, code)
-	LogErrorWithFields(r, err, fields)
+	logErrorWithFields(r, err, nil)
 }
 
 func Fail500(w http.ResponseWriter, r *http.Request, err error) {
@@ -47,7 +38,8 @@ func Fail500(w http.ResponseWriter, r *http.Request, err error) {
 }
 
 func Fail500WithFields(w http.ResponseWriter, r *http.Request, err error, fields log.Fields) {
-	CaptureAndFailWithFields(w, r, err, "Internal server error", http.StatusInternalServerError, fields)
+	http.Error(w, "Internal server error", http.StatusInternalServerError)
+	logErrorWithFields(r, err, fields)
 }
 
 func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
@@ -60,7 +52,7 @@ func printError(r *http.Request, err error, fields log.Fields) {
 			"method": r.Method,
 			"uri":    mask.URL(r.RequestURI),
 		})
-		entry.WithFields(fields).WithError(err).Error("error")
+		entry.WithFields(fields).WithError(err).Error()
 	} else {
 		log.WithFields(fields).WithError(err).Error("unknown error")
 	}

workhorse/internal/helper/helpers_test.go

@@ -2,13 +2,11 @@ package helper
 
 import (
 	"bytes"
-	"fmt"
 	"io"
 	"net/http"
 	"net/http/httptest"
 	"testing"
 
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 )
 
@@ -142,117 +140,3 @@ func TestFail500WorksWithNils(t *testing.T) {
 	require.Equal(t, http.StatusInternalServerError, w.Code)
 	require.Equal(t, "Internal server error\n", body.String())
 }
-
-func TestLogError(t *testing.T) {
-	tests := []struct {
-		name        string
-		method      string
-		uri         string
-		err         error
-		logMatchers []string
-	}{
-		{
-			name: "nil_request",
-			err:  fmt.Errorf("crash"),
-			logMatchers: []string{
-				`level=error msg="unknown error" error=crash`,
-			},
-		},
-		{
-			name: "nil_request_nil_error",
-			err:  nil,
-			logMatchers: []string{
-				`level=error msg="unknown error" error="<nil>"`,
-			},
-		},
-		{
-			name:   "basic_url",
-			method: "GET",
-			uri:    "http://localhost:3000/",
-			err:    fmt.Errorf("error"),
-			logMatchers: []string{
-				`level=error msg=error correlation_id= error=error method=GET uri="http://localhost:3000/"`,
-			},
-		},
-		{
-			name:   "secret_url",
-			method: "GET",
-			uri:    "http://localhost:3000/path?certificate=123&sharedSecret=123&import_url=the_url&my_password_string=password",
-			err:    fmt.Errorf("error"),
-			logMatchers: []string{
-				`level=error msg=error correlation_id= error=error method=GET uri="http://localhost:3000/path\?certificate=\[FILTERED\]&sharedSecret=\[FILTERED\]&import_url=\[FILTERED\]&my_password_string=\[FILTERED\]"`,
-			},
-		},
-	}
-
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			buf := &bytes.Buffer{}
-
-			oldOut := logrus.StandardLogger().Out
-			logrus.StandardLogger().Out = buf
-			defer func() {
-				logrus.StandardLogger().Out = oldOut
-			}()
-
-			var r *http.Request
-			if tt.uri != "" {
-				r = httptest.NewRequest(tt.method, tt.uri, nil)
-			}
-
-			LogError(r, tt.err)
-
-			logString := buf.String()
-			for _, v := range tt.logMatchers {
-				require.Regexp(t, v, logString)
-			}
-		})
-	}
-}
-
-func TestLogErrorWithFields(t *testing.T) {
-	tests := []struct {
-		name       string
-		request    *http.Request
-		err        error
-		fields     map[string]interface{}
-		logMatcher string
-	}{
-		{
-			name:       "nil_request",
-			err:        fmt.Errorf("crash"),
-			fields:     map[string]interface{}{"extra_one": 123},
-			logMatcher: `level=error msg="unknown error" error=crash extra_one=123`,
-		},
-		{
-			name:       "nil_request_nil_error",
-			err:        nil,
-			fields:     map[string]interface{}{"extra_one": 123, "extra_two": "test"},
-			logMatcher: `level=error msg="unknown error" error="<nil>" extra_one=123 extra_two=test`,
-		},
-		{
-			name:       "basic_url",
-			request:    httptest.NewRequest("GET", "http://localhost:3000/", nil),
-			err:        fmt.Errorf("error"),
-			fields:     map[string]interface{}{"extra_one": 123, "extra_two": "test"},
-			logMatcher: `level=error msg=error correlation_id= error=error extra_one=123 extra_two=test method=GET uri="http://localhost:3000/`,
-		},
-	}
-
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			buf := &bytes.Buffer{}
-
-			oldOut := logrus.StandardLogger().Out
-			logrus.StandardLogger().Out = buf
-			defer func() {
-				logrus.StandardLogger().Out = oldOut
-			}()
-
-			LogErrorWithFields(tt.request, tt.err, tt.fields)
-
-			logString := buf.String()
-			require.Contains(t, logString, tt.logMatcher)
-		})
-	}
-}

workhorse/internal/helper/raven.go

@@ -17,7 +17,7 @@ var ravenHeaderBlacklist = []string{
 	"Private-Token",
 }
 
-func captureRavenError(r *http.Request, err error, fields log.Fields) {
+func CaptureRavenError(r *http.Request, err error, fields log.Fields) {
 	client := raven.DefaultClient
 	extra := raven.Extra{}
 

workhorse/internal/imageresizer/image_resizer.go

@@ -19,12 +19,11 @@ import (
 	"github.com/prometheus/client_golang/prometheus/promauto"
 
 	"gitlab.com/gitlab-org/labkit/correlation"
-	"gitlab.com/gitlab-org/labkit/log"
-	"gitlab.com/gitlab-org/labkit/mask"
 	"gitlab.com/gitlab-org/labkit/tracing"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -203,7 +202,7 @@ func (r *Resizer) Inject(w http.ResponseWriter, req *http.Request, paramsData st
 	if err != nil {
 		// Something failed, but we can still write out the original image, so don't return early.
 		// We need to log this separately since the subsequent steps might add other failures.
-		helper.LogErrorWithFields(req, err, *logFields(start, params, &outcome))
+		log.WithRequest(req).WithFields(logFields(start, params, &outcome)).WithError(err).Error()
 	}
 	defer helper.CleanUpProcessGroup(resizeCmd)
 
@@ -410,13 +409,13 @@ func (o *resizeOutcome) error(err error) {
 	o.err = err
 }
 
-func logFields(startTime time.Time, params *resizeParams, outcome *resizeOutcome) *log.Fields {
+func logFields(startTime time.Time, params *resizeParams, outcome *resizeOutcome) log.Fields {
 	var targetWidth, contentType string
 	if params != nil {
 		targetWidth = fmt.Sprint(params.Width)
 		contentType = fmt.Sprint(params.ContentType)
 	}
-	return &log.Fields{
+	return log.Fields{
 		"subsystem":                      logSystem,
 		"written_bytes":                  outcome.bytesWritten,
 		"duration_s":                     time.Since(startTime).Seconds(),
@@ -428,22 +427,17 @@ func logFields(startTime time.Time, params *resizeParams, outcome *resizeOutcome
 }
 
 func handleOutcome(w http.ResponseWriter, req *http.Request, startTime time.Time, params *resizeParams, outcome *resizeOutcome) {
-	logger := log.ContextLogger(req.Context())
-	fields := *logFields(startTime, params, outcome)
+	fields := logFields(startTime, params, outcome)
+	log := log.WithRequest(req).WithFields(fields)
 
 	switch outcome.status {
 	case statusRequestFailure:
 		if outcome.bytesWritten <= 0 {
 			helper.Fail500WithFields(w, req, outcome.err, fields)
 		} else {
-			helper.LogErrorWithFields(req, outcome.err, fields)
+			log.WithError(outcome.err).Error(outcome.status)
 		}
 	default:
-		logger.WithFields(fields).WithFields(
-			log.Fields{
-				"method": req.Method,
-				"uri":    mask.URL(req.RequestURI),
-			},
-		).Printf(outcome.status)
+		log.Info(outcome.status)
 	}
 }

workhorse/internal/log/logging.go

+package log
+
+import (
+	"net/http"
+
+	"github.com/sirupsen/logrus"
+	"gitlab.com/gitlab-org/labkit/log"
+	"gitlab.com/gitlab-org/labkit/mask"
+	"golang.org/x/net/context"
+
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+)
+
+type Fields = log.Fields
+
+type Builder struct {
+	entry  *logrus.Entry
+	fields log.Fields
+	req    *http.Request
+	err    error
+}
+
+func NewBuilder() *Builder {
+	return &Builder{entry: log.WithFields(nil)}
+}
+
+func WithRequest(r *http.Request) *Builder {
+	return NewBuilder().WithRequest(r)
+}
+
+func (b *Builder) WithRequest(r *http.Request) *Builder {
+	if r == nil {
+		return b
+	}
+
+	b.req = r
+	b.WithFields(log.ContextFields(r.Context())).WithFields(
+		Fields{
+			"method": r.Method,
+			"uri":    mask.URL(r.RequestURI),
+		},
+	)
+	return b
+}
+
+func WithFields(fields Fields) *Builder {
+	return NewBuilder().WithFields(fields)
+}
+
+func (b *Builder) WithFields(fields Fields) *Builder {
+	b.fields = fields
+	b.entry = b.entry.WithFields(fields)
+	return b
+}
+
+func WithContextFields(ctx context.Context, fields Fields) *Builder {
+	return WithFields(log.ContextFields(ctx)).WithFields(fields)
+}
+
+func WithError(err error) *Builder {
+	return NewBuilder().WithError(err)
+}
+
+func (b *Builder) WithError(err error) *Builder {
+	b.err = err
+	b.entry = b.entry.WithError(err)
+	return b
+}
+
+func Info(args ...interface{}) {
+	NewBuilder().Info(args...)
+}
+
+func (b *Builder) Info(args ...interface{}) {
+	b.entry.Info(args...)
+}
+
+func Error(args ...interface{}) {
+	NewBuilder().Error(args...)
+}
+
+func (b *Builder) Error(args ...interface{}) {
+	b.entry.Error(args...)
+
+	if b.req != nil && b.err != nil {
+		helper.CaptureRavenError(b.req, b.err, b.fields)
+	}
+}

workhorse/internal/log/logging_test.go

+package log
+
+import (
+	"bytes"
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+func captureLogs(b *Builder, testFn func()) string {
+	buf := &bytes.Buffer{}
+
+	logger := b.entry.Logger
+	oldOut := logger.Out
+	logger.Out = buf
+	defer func() {
+		logger.Out = oldOut
+	}()
+
+	testFn()
+
+	return buf.String()
+}
+
+func TestLogInfo(t *testing.T) {
+	b := NewBuilder()
+	logLine := captureLogs(b, func() {
+		b.Info("an observation")
+	})
+
+	require.Regexp(t, `level=info msg="an observation"`, logLine)
+}
+
+func TestLogError(t *testing.T) {
+	b := NewBuilder()
+	logLine := captureLogs(b, func() {
+		b.WithError(fmt.Errorf("the error")).Error()
+	})
+
+	require.Regexp(t, `level=error error="the error"`, logLine)
+}
+
+func TestLogErrorWithMessage(t *testing.T) {
+	b := NewBuilder()
+	logLine := captureLogs(b, func() {
+		b.WithError(fmt.Errorf("the error")).Error("an error occurred")
+	})
+
+	require.Regexp(t, `level=error msg="an error occurred" error="the error"`, logLine)
+}
+
+func TestLogErrorWithRequest(t *testing.T) {
+	tests := []struct {
+		name        string
+		method      string
+		uri         string
+		err         error
+		logMatchers []string
+	}{
+		{
+			name: "nil_request",
+			err:  fmt.Errorf("cause"),
+			logMatchers: []string{
+				`level=error error=cause`,
+			},
+		},
+		{
+			name: "nil_request_nil_error",
+			err:  nil,
+			logMatchers: []string{
+				`level=error error="<nil>"`,
+			},
+		},
+		{
+			name:   "basic_url",
+			method: "GET",
+			uri:    "http://localhost:3000/",
+			err:    fmt.Errorf("cause"),
+			logMatchers: []string{
+				`level=error correlation_id= error=cause method=GET uri="http://localhost:3000/"`,
+			},
+		},
+		{
+			name:   "secret_url",
+			method: "GET",
+			uri:    "http://localhost:3000/path?certificate=123&sharedSecret=123&import_url=the_url&my_password_string=password",
+			err:    fmt.Errorf("cause"),
+			logMatchers: []string{
+				`level=error correlation_id= error=cause method=GET uri="http://localhost:3000/path\?certificate=\[FILTERED\]&sharedSecret=\[FILTERED\]&import_url=\[FILTERED\]&my_password_string=\[FILTERED\]"`,
+			},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			b := NewBuilder()
+
+			var r *http.Request
+			if tt.uri != "" {
+				r = httptest.NewRequest(tt.method, tt.uri, nil)
+			}
+
+			logLine := captureLogs(b, func() {
+				b.WithRequest(r).WithError(tt.err).Error()
+			})
+
+			for _, v := range tt.logMatchers {
+				require.Regexp(t, v, logLine)
+			}
+		})
+	}
+}
+
+func TestLogErrorWithFields(t *testing.T) {
+	tests := []struct {
+		name       string
+		request    *http.Request
+		err        error
+		fields     map[string]interface{}
+		logMatcher string
+	}{
+		{
+			name:       "nil_request",
+			err:        fmt.Errorf("cause"),
+			fields:     map[string]interface{}{"extra_one": 123},
+			logMatcher: `level=error error=cause extra_one=123`,
+		},
+		{
+			name:       "nil_request_nil_error",
+			err:        nil,
+			fields:     map[string]interface{}{"extra_one": 123, "extra_two": "test"},
+			logMatcher: `level=error error="<nil>" extra_one=123 extra_two=test`,
+		},
+		{
+			name:       "basic_url",
+			request:    httptest.NewRequest("GET", "http://localhost:3000/", nil),
+			err:        fmt.Errorf("cause"),
+			fields:     map[string]interface{}{"extra_one": 123, "extra_two": "test"},
+			logMatcher: `level=error correlation_id= error=cause extra_one=123 extra_two=test method=GET uri="http://localhost:3000/`,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			b := NewBuilder()
+
+			logLine := captureLogs(b, func() {
+				b.WithRequest(tt.request).WithFields(tt.fields).WithError(tt.err).Error()
+			})
+
+			require.Contains(t, logLine, tt.logMatcher)
+		})
+	}
+}

workhorse/internal/redis/keywatcher.go

@@ -10,9 +10,8 @@ import (
 	"github.com/jpillora/backoff"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
-	"gitlab.com/gitlab-org/labkit/log"
 
-	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 var (
@@ -64,13 +63,13 @@ func processInner(conn redis.Conn) error {
 			dataStr := string(v.Data)
 			msg := strings.SplitN(dataStr, "=", 2)
 			if len(msg) != 2 {
-				helper.LogError(nil, fmt.Errorf("keywatcher: invalid notification: %q", dataStr))
+				log.WithError(fmt.Errorf("keywatcher: invalid notification: %q", dataStr)).Error()
 				continue
 			}
 			key, value := msg[0], msg[1]
 			notifyChanWatchers(key, value)
 		case error:
-			helper.LogError(nil, fmt.Errorf("keywatcher: pubsub receive: %v", v))
+			log.WithError(fmt.Errorf("keywatcher: pubsub receive: %v", v)).Error()
 			// Intermittent error, return nil so that it doesn't wait before reconnect
 			return nil
 		}
@@ -101,14 +100,14 @@ func Process() {
 	for {
 		conn, err := dialPubSub(workerDialFunc)
 		if err != nil {
-			helper.LogError(nil, fmt.Errorf("keywatcher: %v", err))
+			log.WithError(fmt.Errorf("keywatcher: %v", err)).Error()
 			time.Sleep(redisReconnectTimeout.Duration())
 			continue
 		}
 		redisReconnectTimeout.Reset()
 
 		if err = processInner(conn); err != nil {
-			helper.LogError(nil, fmt.Errorf("keywatcher: process loop: %v", err))
+			log.WithError(fmt.Errorf("keywatcher: process loop: %v", err)).Error()
 		}
 	}
 }

workhorse/internal/rejectmethods/middleware_test.go

@@ -16,7 +16,7 @@ func TestNewMiddleware(t *testing.T) {
 
 	middleware := NewMiddleware(handler)
 
-	acceptedMethods := []string{"GET", "HEAD", "POST", "PUT", "PATCH", "CONNECT", "OPTIONS", "TRACE"}
+	acceptedMethods := []string{"GET", "HEAD", "POST", "PUT", "PATCH", "DELETE", "CONNECT", "OPTIONS", "TRACE"}
 	for _, method := range acceptedMethods {
 		t.Run(method, func(t *testing.T) {
 			tmpRequest, _ := http.NewRequest(method, "/", nil)

workhorse/internal/sendurl/sendurl.go

@@ -11,11 +11,11 @@ import (
 	"github.com/prometheus/client_golang/prometheus/promauto"
 
 	"gitlab.com/gitlab-org/labkit/correlation"
-	"gitlab.com/gitlab-org/labkit/log"
 	"gitlab.com/gitlab-org/labkit/mask"
 	"gitlab.com/gitlab-org/labkit/tracing"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -159,7 +159,7 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string)
 
 	if err != nil {
 		sendURLRequestsRequestFailed.Inc()
-		helper.LogError(r, fmt.Errorf("SendURL: Copy response: %v", err))
+		log.WithRequest(r).WithError(fmt.Errorf("SendURL: Copy response: %v", err)).Error()
 		return
 	}