diff options
Diffstat (limited to 'workhorse')
28 files changed, 523 insertions, 200 deletions
diff --git a/workhorse/.gitlab-ci.yml b/workhorse/.gitlab-ci.yml index b3377c894e0..69f25fde968 100644 --- a/workhorse/.gitlab-ci.yml +++ b/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' diff --git a/workhorse/CHANGELOG b/workhorse/CHANGELOG index 271928845c1..42c13465ba9 100644 --- a/workhorse/CHANGELOG +++ b/workhorse/CHANGELOG @@ -1,12 +1,14 @@ # 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 diff --git a/workhorse/Makefile b/workhorse/Makefile index 7a8503512df..5661468149b 100644 --- a/workhorse/Makefile +++ b/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) diff --git a/workhorse/PROCESS.md b/workhorse/PROCESS.md index 07f553dd387..797de59d47e 100644 --- a/workhorse/PROCESS.md +++ b/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 diff --git a/workhorse/VERSION b/workhorse/VERSION index 8aa8b5f68bd..8c20f999400 100644 --- a/workhorse/VERSION +++ b/workhorse/VERSION @@ -1 +1 @@ -8.58.2 +8.59.0 diff --git a/workhorse/_support/fmt.sh b/workhorse/_support/fmt.sh new file mode 100755 index 00000000000..b319ac7e328 --- /dev/null +++ b/workhorse/_support/fmt.sh @@ -0,0 +1,25 @@ +#!/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 diff --git a/workhorse/_support/validate-formatting.sh b/workhorse/_support/validate-formatting.sh deleted file mode 100755 index 190f646f8df..00000000000 --- a/workhorse/_support/validate-formatting.sh +++ /dev/null @@ -1,9 +0,0 @@ -#!/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 diff --git a/workhorse/cmd/gitlab-resize-image/main.go b/workhorse/cmd/gitlab-resize-image/main.go index 662efd7306d..81288c645eb 100644 --- a/workhorse/cmd/gitlab-resize-image/main.go +++ b/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) } diff --git a/workhorse/cmd/gitlab-resize-image/png/reader.go b/workhorse/cmd/gitlab-resize-image/png/reader.go new file mode 100644 index 00000000000..8229454ee3b --- /dev/null +++ b/workhorse/cmd/gitlab-resize-image/png/reader.go @@ -0,0 +1,86 @@ +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 +} diff --git a/workhorse/cmd/gitlab-resize-image/png/reader_test.go b/workhorse/cmd/gitlab-resize-image/png/reader_test.go new file mode 100644 index 00000000000..2b2d5df24e9 --- /dev/null +++ b/workhorse/cmd/gitlab-resize-image/png/reader_test.go @@ -0,0 +1,97 @@ +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) +} diff --git a/workhorse/internal/api/api.go b/workhorse/internal/api/api.go index 17fea398029..988bb73f256 100644 --- a/workhorse/internal/api/api.go +++ b/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() } } diff --git a/workhorse/internal/badgateway/roundtripper.go b/workhorse/internal/badgateway/roundtripper.go index a36cc9f4a9a..71bee12ead7 100644 --- a/workhorse/internal/badgateway/roundtripper.go +++ b/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, diff --git a/workhorse/internal/git/archive.go b/workhorse/internal/git/archive.go index b7575be2c02..361e1d00c0b 100644 --- a/workhorse/internal/git/archive.go +++ b/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, ©Error{fmt.Errorf("SendArchive: copy 'git archive' output: %v", err)}) + log.WithRequest(r).WithError(©Error{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 } } diff --git a/workhorse/internal/git/diff.go b/workhorse/internal/git/diff.go index b1a1c17a650..51cadeecb65 100644 --- a/workhorse/internal/git/diff.go +++ b/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, - ©Error{fmt.Errorf("diff.RawDiff: request=%v, err=%v", request, err)}, - ) + log.WithRequest(r).WithError(©Error{fmt.Errorf("diff.RawDiff: %v", err)}).Error() return } } diff --git a/workhorse/internal/git/format-patch.go b/workhorse/internal/git/format-patch.go index db96029b07e..3a65fc2a7a2 100644 --- a/workhorse/internal/git/format-patch.go +++ b/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, - ©Error{fmt.Errorf("diff.RawPatch: request=%v, err=%v", request, err)}, - ) + log.WithRequest(r).WithError(©Error{fmt.Errorf("diff.RawPatch: %v", err)}).Error() return } } diff --git a/workhorse/internal/git/git-http.go b/workhorse/internal/git/git-http.go index 5df20a68bb7..8115d833bb1 100644 --- a/workhorse/internal/git/git-http.go +++ b/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() } }) } diff --git a/workhorse/internal/git/snapshot.go b/workhorse/internal/git/snapshot.go index eb38becbd06..bd9405a28d0 100644 --- a/workhorse/internal/git/snapshot.go +++ b/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() } } diff --git a/workhorse/internal/helper/helpers.go b/workhorse/internal/helper/helpers.go index 5f1e5fc51b3..f9b46181579 100644 --- a/workhorse/internal/helper/helpers.go +++ b/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") } diff --git a/workhorse/internal/helper/helpers_test.go b/workhorse/internal/helper/helpers_test.go index 6a895aded03..93d1ee33d59 100644 --- a/workhorse/internal/helper/helpers_test.go +++ b/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) - }) - } -} diff --git a/workhorse/internal/helper/raven.go b/workhorse/internal/helper/raven.go index ea1d0e1f6cc..898e8ec85f8 100644 --- a/workhorse/internal/helper/raven.go +++ b/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{} diff --git a/workhorse/internal/imageresizer/image_resizer.go b/workhorse/internal/imageresizer/image_resizer.go index 77318ed1c46..69e9496aec2 100644 --- a/workhorse/internal/imageresizer/image_resizer.go +++ b/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) } } diff --git a/workhorse/internal/log/logging.go b/workhorse/internal/log/logging.go new file mode 100644 index 00000000000..c65ec07743a --- /dev/null +++ b/workhorse/internal/log/logging.go @@ -0,0 +1,88 @@ +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) + } +} diff --git a/workhorse/internal/log/logging_test.go b/workhorse/internal/log/logging_test.go new file mode 100644 index 00000000000..1cb6438532e --- /dev/null +++ b/workhorse/internal/log/logging_test.go @@ -0,0 +1,157 @@ +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) + }) + } +} diff --git a/workhorse/internal/redis/keywatcher.go b/workhorse/internal/redis/keywatcher.go index 96e33a64b85..8f3e61b5e9f 100644 --- a/workhorse/internal/redis/keywatcher.go +++ b/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() } } } diff --git a/workhorse/internal/rejectmethods/middleware_test.go b/workhorse/internal/rejectmethods/middleware_test.go index 2921975aeef..ee5a3eb0ade 100644 --- a/workhorse/internal/rejectmethods/middleware_test.go +++ b/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) diff --git a/workhorse/internal/sendurl/sendurl.go b/workhorse/internal/sendurl/sendurl.go index cf3d14a2bf0..8eef6f76ff1 100644 --- a/workhorse/internal/sendurl/sendurl.go +++ b/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 } diff --git a/workhorse/testdata/image_bad_iccp.png b/workhorse/testdata/image_bad_iccp.png Binary files differnew file mode 100644 index 00000000000..a276dd9ee68 --- /dev/null +++ b/workhorse/testdata/image_bad_iccp.png diff --git a/workhorse/testdata/image_stripped_iccp.png b/workhorse/testdata/image_stripped_iccp.png Binary files differnew file mode 100644 index 00000000000..6ed6aee4c30 --- /dev/null +++ b/workhorse/testdata/image_stripped_iccp.png |
