Commit 92010a39 authored by Matthias Käppler's avatar Matthias Käppler Committed by Alessio Caiazza

Reject unknown HTTP methods

too long method name results in too long
prometheus label name, which can crash prometheus
parent a1239653
---
title: Bump workhorse to 8.59.0
merge_request: 51329
author:
type: changed
......@@ -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'
......
# 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
......
......@@ -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)
......
......@@ -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
......
#!/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
#!/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
......@@ -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)
}
......
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
}
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)
}
......@@ -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()
}
}
......
......@@ -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,
......
......@@ -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
}
}
......
......@@ -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
}
}
......@@ -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
}
}
......@@ -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()
}
})
}
......
......@@ -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()
}
}
......@@ -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")
}
......
......@@ -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)
})
}
}
......@@ -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{}
......
......@@ -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)
}
}
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)
}
}
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)
})
}
}
......@@ -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()
}
}
}
......
......@@ -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)
......
......@@ -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
}
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment