Skip to content

Commit

Permalink
Uniform log format fields (#300)
Browse files Browse the repository at this point in the history

* Implemented changes for uniform Log-Format fields

* Fixed null pointer exception at requestField "tls"

* Adjusted changelog, reset changes in couper.hcl

* Inclusion of access log test with more test cases

* Implemented renaming and rearranging from meeting

* Added upstream log test

* Tests done, reset upstream tls/status to rsp field

* Moved line 106 as instructed, reset workspace

* Removed response.tls, renamed and moved realtime

* Moved declaration of timings.total, removed realtime
  • Loading branch information
Buphido authored Aug 27, 2021
1 parent 05b80a5 commit eb1ce9d
Show file tree
Hide file tree
Showing 5 changed files with 404 additions and 29 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand Down
30 changes: 16 additions & 14 deletions logging/access_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 == "" {
Expand All @@ -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

Expand Down Expand Up @@ -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()
Expand All @@ -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()),
Expand All @@ -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)
Expand Down
189 changes: 189 additions & 0 deletions logging/access_log_test.go
Original file line number Diff line number Diff line change
@@ -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)
}
}
}
})
}
}
28 changes: 13 additions & 15 deletions logging/upstream_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -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 {
Expand All @@ -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")
}
}

Expand All @@ -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
Expand All @@ -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
}
Expand All @@ -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
Expand Down Expand Up @@ -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()
}
},
Expand Down
Loading

0 comments on commit eb1ce9d

Please sign in to comment.