Repository: beatlabs/patron
Pull request #341 (2021-02-02 08:52:49)

HTTP Error Logging
## Which problem is this PR solving?

Closes https://github.com/beatlabs/patron/issues/340

## Short description of the changes

The main idea is to parse an environment variable that would act as an allow list: if a handler returns a status code that is present in this list, the error will be logged.

The syntax of the env var is based on https://www.postgresql.org/docs/9.3/rangetypes.html (see 8.17.5. Range Input/Output). We can pass either fixed status code or ranges. For example: `404;[500;600)` means 404 and the range from 500 included to 600 excluded.

* A new `logging.go` file holding the logic of parsing and checking whether a status code should lead to an error
* Modifying `handler.go` to handle logging


codecov[bot]: # [Codecov](https://codecov.io/gh/beatlabs/patron/pull/341?src=pr&el=h1) Report
> Merging [#341](https://codecov.io/gh/beatlabs/patron/pull/341?src=pr&el=desc) (dafcc8c) into [master](https://codecov.io/gh/beatlabs/patron/commit/9d7000e55f221f2b1db2309bebee6a1e319cc394?el=desc) (9d7000e) will **increase** coverage by `0.34%`.
> The diff coverage is `97.29%`.

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

```diff
@@            Coverage Diff             @@
##           master     #341      +/-   ##
==========================================
+ Coverage   73.99%   74.34%   +0.34%     
==========================================
  Files          64       65       +1     
  Lines        3603     3675      +72     
==========================================
+ Hits         2666     2732      +66     
- Misses        835      840       +5     
- Partials      102      103       +1     
```


| [Impacted Files](https://codecov.io/gh/beatlabs/patron/pull/341?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [component/http/handler.go](https://codecov.io/gh/beatlabs/patron/pull/341/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvaGFuZGxlci5nbw==) | `96.39% <60.00%> (-1.74%)` | :arrow_down: |
| [component/http/logging.go](https://codecov.io/gh/beatlabs/patron/pull/341/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2h0dHAvbG9nZ2luZy5nbw==) | `100.00% <100.00%> (ø)` | |
| [component/http/route.go](https://codecov.io/gh/beatlabs/patron/pull/341/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/341/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2FzeW5jL2thZmthL3NpbXBsZS9kdXJhdGlvbl9jbGllbnQuZ28=) | `92.72% <0.00%> (-3.64%)` | :arrow_down: |
| [component/async/sqs/sqs.go](https://codecov.io/gh/beatlabs/patron/pull/341/diff?src=pr&el=tree#diff-Y29tcG9uZW50L2FzeW5jL3Nxcy9zcXMuZ28=) | `78.06% <0.00%> (-1.03%)` | :arrow_down: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/beatlabs/patron/pull/341?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/341?src=pr&el=footer). Last update [9d7000e...4bb0f6c](https://codecov.io/gh/beatlabs/patron/pull/341?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/component/http/logging.go b/component/http/logging.go
new file mode 100644
index 000000000..605e47e48
--- /dev/null
+++ b/component/http/logging.go
@@ -0,0 +1,157 @@
+package http
+
+import (
+	"errors"
+	"fmt"
+	"strconv"
+	"strings"
+)
+
+type intervalType uint32
+
+const (
+	included intervalType = iota // '[' or ']'
+	excluded                     // '(' or ')'
+)
+
+func newStatusCodeLoggerHandler(cfg string) (statusCodeLoggerHandler, error) {
+	cfg = strings.TrimSpace(cfg)
+	if len(cfg) == 0 {
+		return statusCodeLoggerHandler{}, nil
+	}
+
+	splits := strings.Split(cfg, ";")
+	codes := make([]statusCode, len(splits))
+
+	for idx, split := range splits {
+		i, err := strconv.Atoi(split)
+		isNumber := err == nil
+
+		if isNumber {
+			codes[idx] = statusCode{
+				exactCode: i,
+			}
+		} else {
+			codeRange, err := parseRange(split)
+			if err != nil {
+				return statusCodeLoggerHandler{}, fmt.Errorf("failed to parse status code range %q: %w", split, err)
+			}
+
+			codes[idx] = statusCode{
+				rangeCodes: &codeRange,
+			}
+		}
+	}
+	return statusCodeLoggerHandler{
+		codes: codes,
+	}, nil
+}
+
+func parseRange(s string) (statusCodeRange, error) {
+	// Expected ASCII characters so no need to convert into runes
+	if len(s) < 2 {
+		return statusCodeRange{}, errors.New("range format error")
+	}
+
+	startInterval, err := parseStartInterval(s[0])
+	if err != nil {
+		return statusCodeRange{}, err
+	}
+
+	endInterval, err := parseEndInterval(s[len(s)-1])
+	if err != nil {
+		return statusCodeRange{}, err
+	}
+
+	codesWithoutIntervalTypes := s[1 : len(s)-1]
+
+	splits := strings.Split(codesWithoutIntervalTypes, ",")
+	if len(splits) != 2 {
+		return statusCodeRange{}, fmt.Errorf("expected 2 status codes in the range, got %d", len(splits))
+	}
+
+	start, err := strconv.Atoi(splits[0])
+	if err != nil {
+		return statusCodeRange{}, fmt.Errorf("invalid range start %q", splits[0])
+	}
+
+	end, err := strconv.Atoi(splits[1])
+	if err != nil {
+		return statusCodeRange{}, fmt.Errorf("invalid range end %q", splits[1])
+	}
+
+	return statusCodeRange{
+		start:         start,
+		startInterval: startInterval,
+		end:           end,
+		endInterval:   endInterval,
+	}, nil
+}
+
+func parseStartInterval(c uint8) (intervalType, error) {
+	if c == '[' {
+		return included, nil
+	}
+	if c == '(' {
+		return excluded, nil
+	}
+	return 0, fmt.Errorf(`invalid interval type, expected [ or (, got %c`, c)
+}
+
+func parseEndInterval(c uint8) (intervalType, error) {
+	if c == ']' {
+		return included, nil
+	}
+	if c == ')' {
+		return excluded, nil
+	}
+	return 0, fmt.Errorf(`invalid interval type, expected ] or ), got %c`, c)
+}
+
+type statusCode struct {
+	exactCode  int
+	rangeCodes *statusCodeRange
+}
+
+func (s statusCode) isRange() bool {
+	return s.rangeCodes != nil
+}
+
+type statusCodeRange struct {
+	start         int
+	startInterval intervalType
+	end           int
+	endInterval   intervalType
+}
+
+func (s *statusCodeRange) isIncluded(statusCode int) bool {
+	if s.startInterval == included && s.endInterval == included {
+		return statusCode >= s.start && statusCode <= s.end
+	}
+	if s.startInterval == included && s.endInterval == excluded {
+		return statusCode >= s.start && statusCode < s.end
+	}
+	if s.startInterval == excluded && s.endInterval == included {
+		return statusCode > s.start && statusCode <= s.end
+	}
+	return statusCode > s.start && statusCode < s.end
+}
+
+type statusCodeLoggerHandler struct {
+	codes []statusCode
+}
+
+func (s statusCodeLoggerHandler) shouldLog(statusCode int) bool {
+	for _, code := range s.codes {
+		if code.isRange() {
+			if code.rangeCodes.isIncluded(statusCode) {
+				return true
+			}
+		} else {
+			if statusCode == code.exactCode {
+				return true
+			}
+		}
+	}
+	return false
+}
diff --git a/component/http/middleware.go b/component/http/middleware.go
index 0f017c581..541c0765c 100644
--- a/component/http/middleware.go
+++ b/component/http/middleware.go
@@ -3,6 +3,7 @@ package http
 import (
 	"compress/flate"
 	"compress/gzip"
+	"context"
 	"errors"
 	"fmt"
 	"io"
@@ -132,7 +133,7 @@ func NewAuthMiddleware(auth auth.Authenticator) MiddlewareFunc {
 
 // NewLoggingTracingMiddleware creates a MiddlewareFunc that continues a tracing span and finishes it.
 // It also logs the HTTP request on debug logging level
-func NewLoggingTracingMiddleware(path string) MiddlewareFunc {
+func NewLoggingTracingMiddleware(path string, statusCodeLogger statusCodeLoggerHandler) MiddlewareFunc {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			corID := getOrSetCorrelationID(r.Header)
@@ -141,6 +142,7 @@ func NewLoggingTracingMiddleware(path string) MiddlewareFunc {
 			next.ServeHTTP(lw, r)
 			finishSpan(sp, lw.Status(), lw.payload)
 			logRequestResponse(corID, lw, r)
+			statusCodeErrorLogging(r.Context(), statusCodeLogger, lw.Status(), lw.payload, path)
 		})
 	}
 }
@@ -373,6 +375,16 @@ func logRequestResponse(corID string, w *responseWriter, r *http.Request) {
 	log.Sub(info).Debug()
 }
 
+func statusCodeErrorLogging(ctx context.Context, statusCodeLogger statusCodeLoggerHandler, statusCode int, payload []byte, path string) {
+	if !log.Enabled(log.ErrorLevel) {
+		return
+	}
+
+	if statusCodeLogger.shouldLog(statusCode) {
+		log.FromContext(ctx).Error("%s %d error: %v", path, statusCode, string(payload))
+	}
+}
+
 func getOrSetCorrelationID(h http.Header) string {
 	cor, ok := h[correlation.HeaderID]
 	if !ok {
diff --git a/component/http/route.go b/component/http/route.go
index d9b88b8e2..879a30204 100644
--- a/component/http/route.go
+++ b/component/http/route.go
@@ -4,6 +4,7 @@ import (
 	"errors"
 	"fmt"
 	"net/http"
+	"os"
 	"strings"
 
 	"github.com/beatlabs/patron/cache"
@@ -141,6 +142,12 @@ func (rb *RouteBuilder) MethodTrace() *RouteBuilder {
 
 // Build a route.
 func (rb *RouteBuilder) Build() (Route, error) {
+	cfg, _ := os.LookupEnv("PATRON_HTTP_STATUS_ERROR_LOGGING")
+	statusCodeLogger, err := newStatusCodeLoggerHandler(cfg)
+	if err != nil {
+		return Route{}, fmt.Errorf("failed to parse status codes %q: %w", cfg, err)
+	}
+
 	if len(rb.errors) > 0 {
 		return Route{}, errs.Aggregate(rb.errors...)
 	}
@@ -151,7 +158,7 @@ func (rb *RouteBuilder) Build() (Route, error) {
 
 	var middlewares []MiddlewareFunc
 	if rb.trace {
-		middlewares = append(middlewares, NewLoggingTracingMiddleware(rb.path))
+		middlewares = append(middlewares, NewLoggingTracingMiddleware(rb.path, statusCodeLogger))
 	}
 	if rb.authenticator != nil {
 		middlewares = append(middlewares, NewAuthMiddleware(rb.authenticator))
diff --git a/docs/components/HTTP.md b/docs/components/HTTP.md
index 24552d913..c8a3520c0 100644
--- a/docs/components/HTTP.md
+++ b/docs/components/HTTP.md
@@ -161,6 +161,20 @@ func NewCompressionMiddleware(deflateLevel int, ignoreRoutes ...string) Middlewa
 
 ```
 
+### Error Logging
+
+It is possible to configure specific status codes that, if returned by an HTTP handler, the response's error will be logged.
+
+This configuration must be done using the `PATRON_HTTP_STATUS_ERROR_LOGGING` environment variable. The syntax of this variable is based on PostgreSQL syntax and allows providing ranges.
+
+For example, setting this environment variable to `409;[500,600)` that an error will be logged if an HTTP handler returns either:
+* A status code 409
+* A status code greater or equal than 500 (the bracket represents the inclusion) and strictly smaller than 600 (the parenthesis represents the exclusion)
+
+Be it a specific status code or a range; each element must be delimited with `;`.
+
+To enable error logging, we enable route tracing (`WithTrace` option).
+
 ## HTTP Routes
 
 Each HTTP component can contain several routes. These are injected through the `RoutesBuilder`


Test patch:
diff --git a/component/http/logging_test.go b/component/http/logging_test.go
new file mode 100644
index 000000000..3d2691684
--- /dev/null
+++ b/component/http/logging_test.go
@@ -0,0 +1,63 @@
+package http
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+const complexConfig = "200;(210,212);(220,222];[230,232);[240,242]"
+
+func TestStatusCode(t *testing.T) {
+	type args struct {
+		cfg        string
+		statusCode int
+	}
+	tests := map[string]struct {
+		args               args
+		expectedResult     bool
+		expectedParsingErr bool
+	}{
+		"empty":                                    {args: args{cfg: "", statusCode: 400}, expectedResult: false},
+		"single element - true":                    {args: args{cfg: "400", statusCode: 400}, expectedResult: true},
+		"single element - false":                   {args: args{cfg: "400", statusCode: 401}, expectedResult: false},
+		"complex config - single element - true":   {args: args{cfg: complexConfig, statusCode: 200}, expectedResult: true},
+		"complex config - single element - false":  {args: args{cfg: complexConfig, statusCode: 300}, expectedResult: false},
+		"complex config - excl/excl range - true":  {args: args{cfg: complexConfig, statusCode: 211}, expectedResult: true},
+		"complex config - excl/excl range - false": {args: args{cfg: complexConfig, statusCode: 212}, expectedResult: false},
+		"complex config - excl/incl range - true":  {args: args{cfg: complexConfig, statusCode: 222}, expectedResult: true},
+		"complex config - excl/incl range - false": {args: args{cfg: complexConfig, statusCode: 220}, expectedResult: false},
+		"complex config - incl/excl range - true":  {args: args{cfg: complexConfig, statusCode: 230}, expectedResult: true},
+		"complex config - incl/excl range - false": {args: args{cfg: complexConfig, statusCode: 232}, expectedResult: false},
+		"complex config - incl/incl range - true":  {args: args{cfg: complexConfig, statusCode: 240}, expectedResult: true},
+		"complex config - incl/incl range - false": {args: args{cfg: complexConfig, statusCode: 243}, expectedResult: false},
+		"config error - missing code range":        {args: args{cfg: "[200,]"}, expectedParsingErr: true},
+		"config error - invalid start interval":    {args: args{cfg: "x200,201]"}, expectedParsingErr: true},
+		"config error - invalid end interval":      {args: args{cfg: "[200,201x"}, expectedParsingErr: true},
+		"config error - invalid start":             {args: args{cfg: "[2x0,201]"}, expectedParsingErr: true},
+		"config error - invalid end":               {args: args{cfg: "[200,2x1]"}, expectedParsingErr: true},
+		"config error - invalid range":             {args: args{cfg: "[200,201,202]"}, expectedParsingErr: true},
+	}
+	for name, tt := range tests {
+		t.Run(name, func(t *testing.T) {
+			h, err := newStatusCodeLoggerHandler(tt.args.cfg)
+			if tt.expectedParsingErr {
+				assert.Error(t, err)
+			} else {
+				got := h.shouldLog(tt.args.statusCode)
+				assert.Equal(t, tt.expectedResult, got)
+			}
+		})
+	}
+}
+
+func BenchmarkName(b *testing.B) {
+	h, err := newStatusCodeLoggerHandler(complexConfig)
+	assert.NoError(b, err)
+	b.ReportAllocs()
+	b.ResetTimer()
+
+	for i := 0; i < b.N; i++ {
+		_ = h.shouldLog(403)
+	}
+}
diff --git a/component/http/middleware_test.go b/component/http/middleware_test.go
index 5943c76f7..26d07b2c7 100644
--- a/component/http/middleware_test.go
+++ b/component/http/middleware_test.go
@@ -92,7 +92,7 @@ func TestMiddlewares(t *testing.T) {
 		{"auth middleware success", args{next: handler, mws: []MiddlewareFunc{NewAuthMiddleware(&MockAuthenticator{success: true})}}, 202, ""},
 		{"auth middleware false", args{next: handler, mws: []MiddlewareFunc{NewAuthMiddleware(&MockAuthenticator{success: false})}}, 401, "Unauthorized\n"},
 		{"auth middleware error", args{next: handler, mws: []MiddlewareFunc{NewAuthMiddleware(&MockAuthenticator{err: errors.New("auth error")})}}, 500, "Internal Server Error\n"},
-		{"tracing middleware", args{next: handler, mws: []MiddlewareFunc{NewLoggingTracingMiddleware("/index")}}, 202, ""},
+		{"tracing middleware", args{next: handler, mws: []MiddlewareFunc{NewLoggingTracingMiddleware("/index", statusCodeLoggerHandler{})}}, 202, ""},
 		{"recovery middleware from panic 1", args{next: handler, mws: []MiddlewareFunc{NewRecoveryMiddleware(), panicMiddleware("error")}}, 500, "Internal Server Error\n"},
 		{"recovery middleware from panic 2", args{next: handler, mws: []MiddlewareFunc{NewRecoveryMiddleware(), panicMiddleware(errors.New("error"))}}, 500, "Internal Server Error\n"},
 		{"recovery middleware from panic 3", args{next: handler, mws: []MiddlewareFunc{NewRecoveryMiddleware(), panicMiddleware(-1)}}, 500, "Internal Server Error\n"},
@@ -137,8 +137,8 @@ func TestSpanLogError(t *testing.T) {
 		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, "", ""},
+		{"tracing middleware - error", args{next: errorHandler, mws: []MiddlewareFunc{NewLoggingTracingMiddleware("/index", statusCodeLoggerHandler{})}}, http.StatusInternalServerError, "foo", "foo"},
+		{"tracing middleware - success", args{next: successHandler, mws: []MiddlewareFunc{NewLoggingTracingMiddleware("/index", statusCodeLoggerHandler{})}}, http.StatusOK, "", ""},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {