Uniform log format fields

CHANGELOG.md

@@ -38,6 +38,7 @@ If your applications are running in multiple setups, like testing and production
 
 * **Changed**
   * The `sp_acs_url` in the [SAML Block](./docs/REFERENCE.md#saml-block) may now be relative ([#265](https://github.com/avenga/couper/pull/265))
+  * Organized log format fields for uniform access and upstream log ([#300](https://github.com/avenga/couper/pull/300))
 
 * **Fixed**
   * No GZIP compression for small response bodies ([#186](https://github.com/avenga/couper/issues/186))

logging/access_log.go

@@ -43,9 +43,7 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 	nextHandler.ServeHTTP(rw, req)
 	serveDone := time.Now()
 
-	fields := Fields{
-		"proto": req.Proto,
-	}
+	fields := Fields{}
 
 	backendName, _ := req.Context().Value(request.BackendName).(string)
 	if backendName == "" {
@@ -61,6 +59,8 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 
 	requestFields := Fields{
 		"headers": filterHeader(log.conf.RequestHeaders, req.Header),
+		"method":  req.Method,
+		"proto":   "https",
 	}
 	fields["request"] = requestFields
 
@@ -88,8 +88,8 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 	}
 	requestFields["path"] = path.String()
 
-	requestFields["addr"] = req.URL.Host
-	requestFields["host"], requestFields["port"] = splitHostPort(req.URL.Host)
+	requestFields["origin"] = req.URL.Host
+	requestFields["host"], fields["port"] = splitHostPort(req.URL.Host)
 
 	if req.URL.User != nil && req.URL.User.Username() != "" {
 		fields["auth_user"] = req.URL.User.Username()
@@ -104,8 +104,11 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 		writtenBytes = recorder.WrittenBytes()
 	}
 
-	fields["realtime"] = roundMS(serveDone.Sub(startTime))
+	timingResults := Fields{}
+	fields["timings"] = timingResults
+	timingResults["total"] = roundMS(serveDone.Sub(startTime))
 	fields["status"] = statusCode
+	requestFields["status"] = statusCode
 
 	responseFields := Fields{
 		"headers": filterHeader(log.conf.ResponseHeaders, rw.Header()),
@@ -118,22 +121,21 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 	}
 
 	requestFields["tls"] = req.TLS != nil
-	fields["scheme"] = "http"
 	if req.URL.Scheme != "" {
-		fields["scheme"] = req.URL.Scheme
+		requestFields["proto"] = req.URL.Scheme
 	} else if req.TLS != nil && req.TLS.HandshakeComplete {
-		fields["scheme"] = "https"
+		requestFields["proto"] = "https"
 	}
 
-	if requestFields["port"] == "" {
-		if fields["scheme"] == "https" {
-			requestFields["port"] = "443"
+	if fields["port"] == "" {
+		if requestFields["proto"] == "https" {
+			fields["port"] = "443"
 		} else {
-			requestFields["port"] = "80"
+			fields["port"] = "80"
 		}
 	}
 
-	fields["url"] = fields["scheme"].(string) + "://" + req.URL.Host + path.String()
+	fields["url"] = requestFields["proto"].(string) + "://" + req.URL.Host + path.String()
 
 	var err errors.GoError
 	fields["client_ip"], _ = splitHostPort(req.RemoteAddr)

logging/access_log_test.go

@@ -0,0 +1,189 @@
+package logging_test
+
+import (
+	"context"
+	"net/http"
+	"net/http/httptest"
+	"reflect"
+	"testing"
+	"time"
+
+	"github.com/sirupsen/logrus"
+
+	"github.com/avenga/couper/config/request"
+	"github.com/avenga/couper/internal/test"
+	"github.com/avenga/couper/logging"
+	"github.com/avenga/couper/server/writer"
+)
+
+func TestAccessLog_ServeHTTP(t *testing.T) {
+	logger, hook := test.NewLogger()
+
+	defer func() {
+		if t.Failed() {
+			for _, e := range hook.AllEntries() {
+				t.Log(e.String())
+			}
+		}
+	}()
+
+	accessLog := logging.NewAccessLog(logging.DefaultConfig, logger)
+
+	handler := http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
+		rw.WriteHeader(http.StatusNoContent)
+	})
+
+	type testcase struct {
+		description string
+		url         string
+		expFields   logrus.Fields
+	}
+
+	testcases := []testcase{
+		{
+			description: "pathless url",
+			url:         "http://test.com",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"path": "",
+				},
+			},
+		},
+		{
+			description: "proto https",
+			url:         "https://example.com",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"tls":   true,
+					"proto": "https",
+				},
+			},
+		},
+		{
+			description: "proto http",
+			url:         "http://example.com",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"tls":   false,
+					"proto": "http",
+				},
+			},
+		},
+		{
+			description: "method status constant",
+			url:         "http://example.com",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"method": http.MethodGet,
+					"status": 204,
+				},
+				"method": http.MethodGet,
+				"status": 204,
+			},
+		},
+		{
+			description: "explicit port",
+			url:         "http://localhost:8080/",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"host":   "localhost",
+					"origin": "localhost:8080",
+					"path":   "/",
+				},
+				"port": "8080",
+			},
+		},
+		{
+			description: "implicit port https",
+			url:         "https://couper.io/",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"host":   "couper.io",
+					"origin": "couper.io",
+					"path":   "/",
+				},
+				"port": "443",
+			},
+		},
+		{
+			description: "implicit port http",
+			url:         "http://example.com",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"host":   "example.com",
+					"origin": "example.com",
+					"path":   "",
+				},
+				"port": "80",
+			},
+		},
+		{
+			description: "required request fields",
+			url:         "http://localhost:8080/test",
+			expFields: logrus.Fields{
+				"request": logrus.Fields{
+					"tls":    false,
+					"host":   "localhost",
+					"origin": "localhost:8080",
+					"path":   "/test",
+					"method": http.MethodGet,
+					"status": 204,
+					"proto":  "http",
+				},
+				"method": http.MethodGet,
+				"port":   "8080",
+				"uid":    "veryRandom123",
+				"status": 204,
+			},
+		},
+	}
+
+	for _, tc := range testcases {
+		t.Run(tc.description, func(st *testing.T) {
+
+			hook.Reset()
+
+			req := httptest.NewRequest(http.MethodGet, tc.url, nil)
+
+			ctx := context.Background()
+			ctx = context.WithValue(ctx, request.UID, "veryRandom123")
+			//ctx = context.WithValue(ctx, request.ServerName, "myTestServer")
+			req = req.WithContext(ctx)
+
+			rec := httptest.NewRecorder()
+			rw := writer.NewResponseWriter(rec, "")
+			accessLog.ServeHTTP(rw, req, handler, time.Now())
+
+			entry := hook.LastEntry()
+			for key, expFields := range tc.expFields {
+				value, exist := entry.Data[key]
+				if !exist {
+					st.Errorf("Expected log field %s, got nothing", key)
+				}
+
+				switch ef := expFields.(type) {
+				case logrus.Fields:
+					for k, expected := range ef {
+						var result interface{}
+						switch fields := value.(type) {
+						case logging.Fields:
+							r, ok := fields[k]
+							if !ok {
+								st.Errorf("Expected log field %s.%s, got nothing", key, k)
+							}
+							result = r
+						}
+
+						if !reflect.DeepEqual(expected, result) {
+							st.Errorf("Want: %v for key %s, got: %v", expected, k, result)
+						}
+					}
+				default:
+					if !reflect.DeepEqual(expFields, value) {
+						st.Errorf("Want: %v for key %s, got: %v", expFields, key, value)
+					}
+				}
+			}
+		})
+	}
+}

logging/upstream_log.go

@@ -43,7 +43,8 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 	timings, timingsMu := u.withTraceContext(req)
 
 	fields := Fields{
-		"uid": req.Context().Value(request.UID),
+		"uid":    req.Context().Value(request.UID),
+		"method": req.Method,
 	}
 	if h, ok := u.next.(fmt.Stringer); ok {
 		fields["handler"] = h.String()
@@ -53,8 +54,9 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 	}
 
 	requestFields := Fields{
-		"method": req.Method,
 		"name":   req.Context().Value(request.RoundTripName),
+		"method": req.Method,
+		"proto":  req.URL.Scheme,
 	}
 
 	if req.ContentLength > 0 {
@@ -78,10 +80,10 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 	rtDone := time.Now()
 
 	if req.Host != "" {
-		requestFields["addr"] = req.Host
-		requestFields["host"], requestFields["port"] = splitHostPort(req.Host)
-		if requestFields["port"] == "" {
-			delete(requestFields, "port")
+		requestFields["origin"] = req.Host
+		requestFields["host"], fields["port"] = splitHostPort(req.Host)
+		if fields["port"] == "" {
+			delete(fields, "port")
 		}
 	}
 
@@ -102,8 +104,6 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 	} else if user, _, ok := req.BasicAuth(); ok && user != "" {
 		fields["auth_user"] = user
 	}
-	requestFields["proto"] = req.Proto
-	requestFields["scheme"] = req.URL.Scheme
 
 	if tr, ok := req.Context().Value(request.TokenRequest).(string); ok && tr != "" {
 		fields["token_request"] = tr
@@ -113,16 +113,12 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 		}
 	}
 
-	fields["realtime"] = roundMS(rtDone.Sub(rtStart))
-
 	fields["status"] = 0
 	if beresp != nil {
 		fields["status"] = beresp.StatusCode
-
 		responseFields := Fields{
 			"headers": filterHeader(u.config.ResponseHeaders, beresp.Header),
-			"proto":   beresp.Proto,
-			"tls":     beresp.TLS != nil,
+			"status":  beresp.StatusCode,
 		}
 		fields["response"] = responseFields
 	}
@@ -131,7 +127,9 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 		fields["validation"] = validationErrors
 	}
 
-	timingResults := Fields{}
+	timingResults := Fields{
+		"total": roundMS(rtDone.Sub(rtStart)),
+	}
 	timingsMu.RLock()
 	for f, v := range timings { // clone
 		timingResults[f] = v
@@ -199,7 +197,7 @@ func (u *UpstreamLog) withTraceContext(req *http.Request) (Fields, *sync.RWMutex
 		ConnectDone: func(network, addr string, err error) {
 			if err == nil {
 				mapMu.Lock()
-				timings["connect"] = roundMS(time.Since(timeConnect))
+				timings["tcp"] = roundMS(time.Since(timeConnect))
 				mapMu.Unlock()
 			}
 		},