Log duration_ms when Workhorse hits a bad gateway

Previously when the upstream application (e.g. Unicorn) timed out,
Workhorse would report an error message of the form:

```json
{
  "correlation_id": "k4mKg0snXG3",
  "error": "badgateway: failed after 61s: EOF",
  "level": "error",
  "method": "GET",
  "msg": "error",
  "time": "2019-12-02T22:05:09-08:00",
  "uri": "/admin"
}
```

Since Sentry attempts to group similar events by some fingerprint that
includes the message, the changes in timings would trick Sentry into
creating a new event. To avoid that, the new log message now looks like:

```json
{
  "correlation_id": "k4mKg0snXG3",
  "duration_ms": 60599,
  "error": "badgateway: failed to receive response: EOF",
  "level": "error",
  "method": "GET",
  "msg": "error",
  "time": "2019-12-02T22:05:09-08:00",
  "uri": "/admin"
}
```

The inclusion of `duration_ms` and the standardized `error` message makes
it easier for users to filter and parse this error.

internal/badgateway/roundtripper.go

@@ -7,6 +7,8 @@ import (
 	"net/http"
 	"time"
 
+	"gitlab.com/gitlab-org/labkit/log"
+
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
 )
 
@@ -37,9 +39,11 @@ func (t *roundTripper) RoundTrip(r *http.Request) (*http.Response, error) {
 	// and administrators expect to see a 502 error. To show 502s
 	// instead of 500s we catch the RoundTrip error here and inject a
 	// 502 response.
-	helper.LogError(
+	fields := log.Fields{"duration_ms": int64(time.Since(start).Seconds() * 1000)}
+	helper.LogErrorWithFields(
 		r,
-		&sentryError{fmt.Errorf("badgateway: failed after %.fs: %v", time.Since(start).Seconds(), err)},
+		&sentryError{fmt.Errorf("badgateway: failed to receive response: %v", err)},
+		fields,
 	)
 
 	message := "GitLab is not responding"

internal/helper/helpers.go

@@ -21,11 +21,15 @@ 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) {
 	if err != nil {
-		captureRavenError(r, err)
+		captureRavenError(r, err, fields)
 	}
 
-	printError(r, err)
+	printError(r, err, fields)
 }
 
 func CaptureAndFail(w http.ResponseWriter, r *http.Request, err error, msg string, code int) {
@@ -41,14 +45,15 @@ func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
 	CaptureAndFail(w, r, err, "Request Entity Too Large", http.StatusRequestEntityTooLarge)
 }
 
-func printError(r *http.Request, err error) {
+func printError(r *http.Request, err error, fields log.Fields) {
 	if r != nil {
-		log.WithContextFields(r.Context(), log.Fields{
+		entry := log.WithContextFields(r.Context(), log.Fields{
 			"method": r.Method,
 			"uri":    mask.URL(r.RequestURI),
-		}).WithError(err).Error("error")
+		})
+		entry.WithFields(fields).WithError(err).Error("error")
 	} else {
-		log.WithError(err).Error("unknown error")
+		log.WithFields(fields).WithError(err).Error("unknown error")
 	}
 }
 

internal/helper/helpers_test.go

@@ -210,3 +210,50 @@ func TestLogError(t *testing.T) {
 		})
 	}
 }
+
+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)
+		})
+	}
+}

internal/helper/raven.go

@@ -8,6 +8,8 @@ import (
 
 	//lint:ignore SA1019 this was recently deprecated. Update workhorse to use labkit errortracking package.
 	correlation "gitlab.com/gitlab-org/labkit/correlation/raven"
+
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 var ravenHeaderBlacklist = []string{
@@ -15,10 +17,14 @@ var ravenHeaderBlacklist = []string{
 	"Private-Token",
 }
 
-func captureRavenError(r *http.Request, err error) {
+func captureRavenError(r *http.Request, err error, fields log.Fields) {
 	client := raven.DefaultClient
 	extra := raven.Extra{}
 
+	for k, v := range fields {
+		extra[k] = v
+	}
+
 	interfaces := []raven.Interface{}
 	if r != nil {
 		CleanHeadersForRaven(r)