Commit bb5dc3d6 authored by Matthias Käppler's avatar Matthias Käppler Committed by Jacob Vosmaer

Refactor logging helpers to reduce signature creep

parent d804172f
---
title: Extract logging concerns into a separate module
merge_request:
author:
type: other
...@@ -18,6 +18,8 @@ import ( ...@@ -18,6 +18,8 @@ import (
"gitlab.com/gitlab-org/gitlab-workhorse/internal/config" "gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly" "gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/secret" "gitlab.com/gitlab-org/gitlab-workhorse/internal/secret"
) )
...@@ -322,7 +324,7 @@ func passResponseBack(httpResponse *http.Response, w http.ResponseWriter, r *htt ...@@ -322,7 +324,7 @@ func passResponseBack(httpResponse *http.Response, w http.ResponseWriter, r *htt
} }
w.WriteHeader(httpResponse.StatusCode) w.WriteHeader(httpResponse.StatusCode)
if _, err := io.Copy(w, responseBody); err != nil { if _, err := io.Copy(w, responseBody); err != nil {
helper.LogError(r, err) log.WithRequest(r).WithError(err).Error()
} }
} }
......
...@@ -9,9 +9,7 @@ import ( ...@@ -9,9 +9,7 @@ import (
"strings" "strings"
"time" "time"
"gitlab.com/gitlab-org/labkit/log" "gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
) )
// Error is a custom error for pretty Sentry 'issues' // Error is a custom error for pretty Sentry 'issues'
...@@ -42,11 +40,7 @@ func (t *roundTripper) RoundTrip(r *http.Request) (*http.Response, error) { ...@@ -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 // instead of 500s we catch the RoundTrip error here and inject a
// 502 response. // 502 response.
fields := log.Fields{"duration_ms": int64(time.Since(start).Seconds() * 1000)} fields := log.Fields{"duration_ms": int64(time.Since(start).Seconds() * 1000)}
helper.LogErrorWithFields( log.WithRequest(r).WithFields(fields).WithError(&sentryError{fmt.Errorf("badgateway: failed to receive response: %v", err)}).Error()
r,
&sentryError{fmt.Errorf("badgateway: failed to receive response: %v", err)},
fields,
)
injectedResponse := &http.Response{ injectedResponse := &http.Response{
StatusCode: http.StatusBadGateway, StatusCode: http.StatusBadGateway,
......
...@@ -24,6 +24,7 @@ import ( ...@@ -24,6 +24,7 @@ import (
"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly" "gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata" "gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
) )
...@@ -116,14 +117,14 @@ func (a *archive) Inject(w http.ResponseWriter, r *http.Request, sendData string ...@@ -116,14 +117,14 @@ func (a *archive) Inject(w http.ResponseWriter, r *http.Request, sendData string
setArchiveHeaders(w, format, archiveFilename) setArchiveHeaders(w, format, archiveFilename)
w.WriteHeader(200) // Don't bother with HTTP 500 from this point on, just return w.WriteHeader(200) // Don't bother with HTTP 500 from this point on, just return
if _, err := io.Copy(w, reader); err != nil { 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 return
} }
if cacheEnabled { if cacheEnabled {
err := finalizeCachedArchive(tempFile, params.ArchivePath) err := finalizeCachedArchive(tempFile, params.ArchivePath)
if err != nil { 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 return
} }
} }
......
...@@ -8,6 +8,7 @@ import ( ...@@ -8,6 +8,7 @@ import (
"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly" "gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata" "gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
) )
...@@ -39,10 +40,7 @@ func (d *diff) Inject(w http.ResponseWriter, r *http.Request, sendData string) { ...@@ -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 { if err := diffClient.SendRawDiff(ctx, w, request); err != nil {
helper.LogError( log.WithRequest(r).WithError(&copyError{fmt.Errorf("diff.RawDiff: %v", err)}).Error()
r,
&copyError{fmt.Errorf("diff.RawDiff: request=%v, err=%v", request, err)},
)
return return
} }
} }
...@@ -8,6 +8,7 @@ import ( ...@@ -8,6 +8,7 @@ import (
"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly" "gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata" "gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
) )
...@@ -39,10 +40,7 @@ func (p *patch) Inject(w http.ResponseWriter, r *http.Request, sendData string) ...@@ -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 { if err := diffClient.SendRawPatch(ctx, w, request); err != nil {
helper.LogError( log.WithRequest(r).WithError(&copyError{fmt.Errorf("diff.RawPatch: %v", err)}).Error()
r,
&copyError{fmt.Errorf("diff.RawPatch: request=%v, err=%v", request, err)},
)
return return
} }
} }
...@@ -12,7 +12,7 @@ import ( ...@@ -12,7 +12,7 @@ import (
"sync" "sync"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/api" "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 ( const (
...@@ -54,7 +54,7 @@ func postRPCHandler(a *api.API, name string, handler func(*HttpResponseWriter, * ...@@ -54,7 +54,7 @@ func postRPCHandler(a *api.API, name string, handler func(*HttpResponseWriter, *
// no-op. It never reaches net/http because GitHttpResponseWriter calls // no-op. It never reaches net/http because GitHttpResponseWriter calls
// WriteHeader on its underlying ResponseWriter at most once. // WriteHeader on its underlying ResponseWriter at most once.
w.WriteHeader(500) 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 ( ...@@ -9,6 +9,7 @@ import (
"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly" "gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata" "gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
) )
...@@ -59,6 +60,6 @@ func (s *snapshot) Inject(w http.ResponseWriter, r *http.Request, sendData strin ...@@ -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 w.WriteHeader(http.StatusOK) // Errors aren't detectable beyond this point
if _, err := io.Copy(w, reader); err != nil { 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 ( ...@@ -20,13 +20,9 @@ import (
const NginxResponseBufferHeader = "X-Accel-Buffering" const NginxResponseBufferHeader = "X-Accel-Buffering"
func LogError(r *http.Request, err error) { func logErrorWithFields(r *http.Request, err error, fields log.Fields) {
LogErrorWithFields(r, err, nil)
}
func LogErrorWithFields(r *http.Request, err error, fields log.Fields) {
if err != nil { if err != nil {
captureRavenError(r, err, fields) CaptureRavenError(r, err, fields)
} }
printError(r, err, fields) printError(r, err, fields)
...@@ -34,12 +30,7 @@ func LogErrorWithFields(r *http.Request, err error, fields log.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) { func CaptureAndFail(w http.ResponseWriter, r *http.Request, err error, msg string, code int) {
http.Error(w, msg, code) http.Error(w, msg, code)
LogError(r, err) logErrorWithFields(r, err, nil)
}
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)
} }
func Fail500(w http.ResponseWriter, r *http.Request, err error) { func Fail500(w http.ResponseWriter, r *http.Request, err error) {
...@@ -47,7 +38,8 @@ 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) { 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) { func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
...@@ -60,7 +52,7 @@ func printError(r *http.Request, err error, fields log.Fields) { ...@@ -60,7 +52,7 @@ func printError(r *http.Request, err error, fields log.Fields) {
"method": r.Method, "method": r.Method,
"uri": mask.URL(r.RequestURI), "uri": mask.URL(r.RequestURI),
}) })
entry.WithFields(fields).WithError(err).Error("error") entry.WithFields(fields).WithError(err).Error()
} else { } else {
log.WithFields(fields).WithError(err).Error("unknown error") log.WithFields(fields).WithError(err).Error("unknown error")
} }
......
...@@ -2,13 +2,11 @@ package helper ...@@ -2,13 +2,11 @@ package helper
import ( import (
"bytes" "bytes"
"fmt"
"io" "io"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"testing" "testing"
"github.com/sirupsen/logrus"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
) )
...@@ -142,117 +140,3 @@ func TestFail500WorksWithNils(t *testing.T) { ...@@ -142,117 +140,3 @@ func TestFail500WorksWithNils(t *testing.T) {
require.Equal(t, http.StatusInternalServerError, w.Code) require.Equal(t, http.StatusInternalServerError, w.Code)
require.Equal(t, "Internal server error\n", body.String()) 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{ ...@@ -17,7 +17,7 @@ var ravenHeaderBlacklist = []string{
"Private-Token", "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 client := raven.DefaultClient
extra := raven.Extra{} extra := raven.Extra{}
......
...@@ -19,12 +19,11 @@ import ( ...@@ -19,12 +19,11 @@ import (
"github.com/prometheus/client_golang/prometheus/promauto" "github.com/prometheus/client_golang/prometheus/promauto"
"gitlab.com/gitlab-org/labkit/correlation" "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/labkit/tracing"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/config" "gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata" "gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
) )
...@@ -203,7 +202,7 @@ func (r *Resizer) Inject(w http.ResponseWriter, req *http.Request, paramsData st ...@@ -203,7 +202,7 @@ func (r *Resizer) Inject(w http.ResponseWriter, req *http.Request, paramsData st
if err != nil { if err != nil {
// Something failed, but we can still write out the original image, so don't return early. // 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. // 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) defer helper.CleanUpProcessGroup(resizeCmd)
...@@ -410,13 +409,13 @@ func (o *resizeOutcome) error(err error) { ...@@ -410,13 +409,13 @@ func (o *resizeOutcome) error(err error) {
o.err = err 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 var targetWidth, contentType string
if params != nil { if params != nil {
targetWidth = fmt.Sprint(params.Width) targetWidth = fmt.Sprint(params.Width)
contentType = fmt.Sprint(params.ContentType) contentType = fmt.Sprint(params.ContentType)
} }
return &log.Fields{ return log.Fields{
"subsystem": logSystem, "subsystem": logSystem,
"written_bytes": outcome.bytesWritten, "written_bytes": outcome.bytesWritten,
"duration_s": time.Since(startTime).Seconds(), "duration_s": time.Since(startTime).Seconds(),
...@@ -428,22 +427,17 @@ func logFields(startTime time.Time, params *resizeParams, outcome *resizeOutcome ...@@ -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) { 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 { switch outcome.status {
case statusRequestFailure: case statusRequestFailure:
if outcome.bytesWritten <= 0 { if outcome.bytesWritten <= 0 {
helper.Fail500WithFields(w, req, outcome.err, fields) helper.Fail500WithFields(w, req, outcome.err, fields)
} else { } else {
helper.LogErrorWithFields(req, outcome.err, fields) log.WithError(outcome.err).Error(outcome.status)
} }
default: default:
logger.WithFields(fields).WithFields( log.Info(outcome.status)
log.Fields{
"method": req.Method,
"uri": mask.URL(req.RequestURI),
},
).Printf(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 ( ...@@ -10,9 +10,8 @@ import (
"github.com/jpillora/backoff" "github.com/jpillora/backoff"
"github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto" "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 ( var (
...@@ -64,13 +63,13 @@ func processInner(conn redis.Conn) error { ...@@ -64,13 +63,13 @@ func processInner(conn redis.Conn) error {
dataStr := string(v.Data) dataStr := string(v.Data)
msg := strings.SplitN(dataStr, "=", 2) msg := strings.SplitN(dataStr, "=", 2)
if len(msg) != 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 continue
} }
key, value := msg[0], msg[1] key, value := msg[0], msg[1]
notifyChanWatchers(key, value) notifyChanWatchers(key, value)
case error: 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 // Intermittent error, return nil so that it doesn't wait before reconnect
return nil return nil
} }
...@@ -101,14 +100,14 @@ func Process() { ...@@ -101,14 +100,14 @@ func Process() {
for { for {
conn, err := dialPubSub(workerDialFunc) conn, err := dialPubSub(workerDialFunc)
if err != nil { if err != nil {
helper.LogError(nil, fmt.Errorf("keywatcher: %v", err)) log.WithError(fmt.Errorf("keywatcher: %v", err)).Error()
time.Sleep(redisReconnectTimeout.Duration()) time.Sleep(redisReconnectTimeout.Duration())
continue continue
} }
redisReconnectTimeout.Reset() redisReconnectTimeout.Reset()
if err = processInner(conn); err != nil { 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()
} }
} }
} }
......
...@@ -11,11 +11,11 @@ import ( ...@@ -11,11 +11,11 @@ import (
"github.com/prometheus/client_golang/prometheus/promauto" "github.com/prometheus/client_golang/prometheus/promauto"
"gitlab.com/gitlab-org/labkit/correlation" "gitlab.com/gitlab-org/labkit/correlation"
"gitlab.com/gitlab-org/labkit/log"
"gitlab.com/gitlab-org/labkit/mask" "gitlab.com/gitlab-org/labkit/mask"
"gitlab.com/gitlab-org/labkit/tracing" "gitlab.com/gitlab-org/labkit/tracing"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper" "gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata" "gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
) )
...@@ -159,7 +159,7 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string) ...@@ -159,7 +159,7 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string)
if err != nil { if err != nil {
sendURLRequestsRequestFailed.Inc() 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 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