Repository: beatlabs/patron
Pull request #242 (2020-07-28 11:54:18)

Add a tracing log field if an HTTP service returns an error
## Which problem is this PR solving?

https://github.com/beatlabs/patron/issues/241

## Short description of the changes

* Modify `responseWriter` to add a payload byte slice
* Change `responseWriter.Write()` to store the payload written
* Retrieve this payload in the tracing middleware modify `finishSpan` to add a log field (only if there is an error)


mantzas: @teivah this closes the same issue... is this on purpose?

teivah: > @teivah this closes the same issue... is this on purpose?

@mantzas Sorry, too much tracing PRs going on right now ^^ I mixed the ticket, it's fixed.
mantzas: @teivah also linting seems to fail.
codecov[bot]: # [Codecov](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=h1) Report
> Merging [#242](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=desc) into [master](https://codecov.io/gh/beatlabs/patron/commit/f8ebb41faf5e8c7d6b980c516fa5ae01e972a410&el=desc) will **increase** coverage by `0.14%`.
> The diff coverage is `76.16%`.

[![Impacted file tree graph](https://codecov.io/gh/beatlabs/patron/pull/242/graphs/tree.svg?width=650&height=150&src=pr&token=sxY15rXW1X)](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master     #242      +/-   ##
==========================================
+ Coverage   73.07%   73.22%   +0.14%     
==========================================
  Files          57       61       +4     
  Lines        3332     3656     +324     
==========================================
+ Hits         2435     2677     +242     
- Misses        835      904      +69     
- Partials       62       75      +13     
```


| [Impacted Files](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [component/http/cache/route.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvY2FjaGUvcm91dGUuZ28=) | `49.20% <49.20%> (ø)` | |
| [component/http/cache/metric.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvY2FjaGUvbWV0cmljLmdv) | `63.33% <63.33%> (ø)` | |
| [component/http/cache/cache.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvY2FjaGUvY2FjaGUuZ28=) | `81.96% <81.96%> (ø)` | |
| [component/http/middleware.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvbWlkZGxld2FyZS5nbw==) | `91.12% <82.35%> (-1.60%)` | :arrow_down: |
| [component/http/cache/model.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvY2FjaGUvbW9kZWwuZ28=) | `90.90% <90.90%> (ø)` | |
| [component/http/handler.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvaGFuZGxlci5nbw==) | `98.05% <90.90%> (+0.01%)` | :arrow_up: |
| [component/http/http.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvaHR0cC5nbw==) | `100.00% <100.00%> (ø)` | |
| [component/http/route.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvcm91dGUuZ28=) | `100.00% <100.00%> (ø)` | |
| [component/async/kafka/simple/duration\_client.go](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2FzeW5jL2thZmthL3NpbXBsZS9kdXJhdGlvbl9jbGllbnQuZ28=) | `93.75% <0.00%> (-3.13%)` | :arrow_down: |
| ... and [4 more](https://codecov.io/gh/beatlabs/patron/pull/242/diff?src=pr&el=tree-more) | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=footer). Last update [7471d01...19233f3](https://codecov.io/gh/beatlabs/patron/pull/242?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).

teivah: @mantzas Fixed.

Patch:
diff --git a/component/http/middleware.go b/component/http/middleware.go
index a05bf800b..a6f1fb05d 100644
--- a/component/http/middleware.go
+++ b/component/http/middleware.go
@@ -13,15 +13,18 @@ import (
 	"github.com/google/uuid"
 	"github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
+	tracinglog "github.com/opentracing/opentracing-go/log"
 )
 
 const (
 	serverComponent = "http-server"
+	fieldNameError  = "error"
 )
 
 type responseWriter struct {
 	status              int
 	statusHeaderWritten bool
+	payload             []byte
 	writer              http.ResponseWriter
 }
 
@@ -47,6 +50,8 @@ func (w *responseWriter) Write(d []byte) (int, error) {
 		return value, err
 	}
 
+	w.payload = d
+
 	if !w.statusHeaderWritten {
 		w.status = http.StatusOK
 		w.statusHeaderWritten = true
@@ -118,7 +123,7 @@ func NewLoggingTracingMiddleware(path string) MiddlewareFunc {
 			sp, r := span(path, corID, r)
 			lw := newResponseWriter(w)
 			next.ServeHTTP(lw, r)
-			finishSpan(sp, lw.Status())
+			finishSpan(sp, lw.Status(), lw.payload)
 			logRequestResponse(corID, lw, r)
 		})
 	}
@@ -210,9 +215,13 @@ func span(path, corID string, r *http.Request) (opentracing.Span, *http.Request)
 	return sp, r.WithContext(opentracing.ContextWithSpan(r.Context(), sp))
 }
 
-func finishSpan(sp opentracing.Span, code int) {
+func finishSpan(sp opentracing.Span, code int, payload []byte) {
 	ext.HTTPStatusCode.Set(sp, uint16(code))
-	ext.Error.Set(sp, code >= http.StatusInternalServerError)
+	isError := code >= http.StatusInternalServerError
+	if isError && len(payload) != 0 {
+		sp.LogFields(tracinglog.String(fieldNameError, string(payload)))
+	}
+	ext.Error.Set(sp, isError)
 	sp.Finish()
 }
 


Test patch:
diff --git a/component/http/middleware_test.go b/component/http/middleware_test.go
index 00626223b..4589c3fc4 100644
--- a/component/http/middleware_test.go
+++ b/component/http/middleware_test.go
@@ -6,7 +6,10 @@ import (
 	"net/http/httptest"
 	"testing"
 
+	"github.com/opentracing/opentracing-go"
+	"github.com/opentracing/opentracing-go/mocktracer"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 // A middleware generator that tags resp for assertions
@@ -105,6 +108,56 @@ func TestMiddlewares(t *testing.T) {
 	}
 }
 
+// TestSpanLogError tests whether an HTTP handler with a tracing middleware adds a log event in case of we return an error.
+func TestSpanLogError(t *testing.T) {
+	mtr := mocktracer.New()
+	opentracing.SetGlobalTracer(mtr)
+
+	successHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusOK)
+	})
+	errorHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusInternalServerError)
+		_, err := w.Write([]byte("foo"))
+		require.NoError(t, err)
+	})
+
+	r, err := http.NewRequest("POST", "/test", nil)
+	assert.NoError(t, err)
+
+	type args struct {
+		next http.Handler
+		mws  []MiddlewareFunc
+	}
+	tests := []struct {
+		name                 string
+		args                 args
+		expectedCode         int
+		expectedBody         string
+		expectedSpanLogError string
+	}{
+		{"tracing middleware - error", args{next: errorHandler, mws: []MiddlewareFunc{NewLoggingTracingMiddleware("/index")}}, http.StatusInternalServerError, "foo", "foo"},
+		{"tracing middleware - success", args{next: successHandler, mws: []MiddlewareFunc{NewLoggingTracingMiddleware("/index")}}, http.StatusOK, "", ""},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			mtr.Reset()
+			rc := httptest.NewRecorder()
+			rw := newResponseWriter(rc)
+			tt.args.next = MiddlewareChain(tt.args.next, tt.args.mws...)
+			tt.args.next.ServeHTTP(rw, r)
+			assert.Equal(t, tt.expectedCode, rw.Status())
+			assert.Equal(t, tt.expectedBody, rc.Body.String())
+
+			if tt.expectedSpanLogError != "" {
+				require.Equal(t, 1, len(mtr.FinishedSpans()))
+				spanLogError := getSpanLogError(t, mtr.FinishedSpans()[0])
+				assert.Equal(t, tt.expectedSpanLogError, spanLogError)
+			}
+		})
+	}
+}
+
 func TestResponseWriter(t *testing.T) {
 	rc := httptest.NewRecorder()
 	rw := newResponseWriter(rc)
@@ -118,3 +171,22 @@ func TestResponseWriter(t *testing.T) {
 	assert.True(t, rw.statusHeaderWritten, "expected to be true")
 	assert.Equal(t, "test", rc.Body.String(), "body expected to be test but was %s", rc.Body.String())
 }
+
+func getSpanLogError(t *testing.T, span *mocktracer.MockSpan) string {
+	logs := span.Logs()
+	if len(logs) == 0 {
+		assert.FailNow(t, "empty logs")
+		return ""
+	}
+
+	for _, log := range logs {
+		for _, field := range log.Fields {
+			if field.Key == fieldNameError {
+				return field.ValueString
+			}
+		}
+	}
+
+	assert.FailNowf(t, "missing logs", "missing field %s", fieldNameError)
+	return ""
+}