From 4357d1a18a770ad5a8431add1a23991df9fe950a Mon Sep 17 00:00:00 2001 From: Sebastian Mancke Date: Fri, 24 Jun 2016 21:58:59 +0200 Subject: [PATCH] transport correlation in all logs --- composition/composition_handler.go | 8 +++---- composition/fetch_definition.go | 4 +++- logging/correlation_id.go | 10 ++++---- logging/logger.go | 22 ++++++++++------- logging/logger_test.go | 5 ++-- util/cookie.go | 38 ++++++++++++++++++++++++++++++ util/cookie_test.go | 32 +++++++++++++++++++++++++ 7 files changed, 97 insertions(+), 22 deletions(-) create mode 100644 util/cookie.go create mode 100644 util/cookie_test.go diff --git a/composition/composition_handler.go b/composition/composition_handler.go index 064b4a1..9cb0dad 100644 --- a/composition/composition_handler.go +++ b/composition/composition_handler.go @@ -1,7 +1,7 @@ package composition import ( - log "github.com/Sirupsen/logrus" + "github.com/tarent/lib-compose/logging" "io" "net/http" "strconv" @@ -57,11 +57,11 @@ func (agg *CompositionHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) mergeContext.AddContent(res) } else if res.Def.Required { - log.WithField("fetchResult", res).Errorf("error loading content from: %v", res.Def.URL) + logging.Application(r.Header).WithField("fetchResult", res).Errorf("error loading content from: %v", res.Def.URL) res.Def.ErrHandler.Handle(res.Err, res.Content.HttpStatusCode(), w, r) return } else { - log.WithField("fetchResult", res).Warnf("optional content not loaded: %v", res.Def.URL) + logging.Application(r.Header).WithField("fetchResult", res).Warnf("optional content not loaded: %v", res.Def.URL) } } @@ -79,7 +79,7 @@ func (agg *CompositionHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) html, err := mergeContext.GetHtml() if err != nil { - log.Error(err.Error()) + logging.Application(r.Header).Error(err.Error()) http.Error(w, "Internal Server Error: "+err.Error(), 500) return } diff --git a/composition/fetch_definition.go b/composition/fetch_definition.go index 8dac3c7..28fed88 100644 --- a/composition/fetch_definition.go +++ b/composition/fetch_definition.go @@ -26,7 +26,9 @@ var ForwardRequestHeaders = []string{ "Pragma", "Referer", "Transfer-Encoding", - "X-Forwarded-Host"} + "X-Forwarded-Host", + "X-Correlation-Id", +} // ForwardResponseHeaders are those headers, // which are incuded from the servers backend response to the client. diff --git a/logging/correlation_id.go b/logging/correlation_id.go index 607f263..bc4c361 100644 --- a/logging/correlation_id.go +++ b/logging/correlation_id.go @@ -1,6 +1,7 @@ package logging import ( + "github.com/tarent/lib-compose/util" "math/rand" "net/http" "time" @@ -39,12 +40,11 @@ func randStringBytes(n int) string { return string(b) } -// GetCorrelationId returns the correlation from of the request. -func GetUserCorrelationId(r *http.Request) string { +// GetCorrelationId returns the users correlation id of the headers. +func GetUserCorrelationId(h http.Header) string { if UserCorrelationCookie != "" { - c, err := r.Cookie(UserCorrelationCookie) - if err == nil { - return c.Value + if value, found := util.ReadCookieValue(h, UserCorrelationCookie); found { + return value } } return "" diff --git a/logging/logger.go b/logging/logger.go index 191007c..a42fe63 100644 --- a/logging/logger.go +++ b/logging/logger.go @@ -16,6 +16,8 @@ var Logger *logrus.Logger // The of cookies which should not be logged var AccessLogCookiesBlacklist = []string{} +var LifecycleEnvVars = []string{"BUILD_NUMBER", "BUILD_HASH", "BUILD_DATE"} + func init() { Set("info", false) } @@ -88,7 +90,7 @@ func access(r *http.Request, start time.Time, statusCode int, err error) *logrus fields[logrus.ErrorKey] = err.Error() } - setCorrelationIds(fields, r) + setCorrelationIds(fields, r.Header) cookies := map[string]string{} for _, c := range r.Cookies() { @@ -119,7 +121,7 @@ func Call(r *http.Request, resp *http.Response, start time.Time, err error) { "duration": time.Since(start).Nanoseconds() / 1000000, } - setCorrelationIds(fields, r) + setCorrelationIds(fields, r.Header) if err != nil { fields[logrus.ErrorKey] = err.Error() @@ -148,11 +150,11 @@ func Call(r *http.Request, resp *http.Response, start time.Time, err error) { // Return a log entry for application logs, // prefilled with the correlation ids out of the supplied request. -func Application(r *http.Request) *logrus.Entry { +func Application(h http.Header) *logrus.Entry { fields := logrus.Fields{ "type": "application", } - setCorrelationIds(fields, r) + setCorrelationIds(fields, h) return Logger.WithFields(fields) } @@ -170,8 +172,10 @@ func LifecycleStart(appName string, args interface{}) { } fields["type"] = "lifecycle" fields["event"] = "start" - if os.Getenv("BUILD_NUMBER") != "" { - fields["build_number"] = os.Getenv("BUILD_NUMBER") + for _, env := range LifecycleEnvVars { + if os.Getenv(env) != "" { + fields[strings.ToLower(env)] = os.Getenv(env) + } } Logger.WithFields(fields).Infof("starting application: %v", appName) @@ -210,13 +214,13 @@ func getRemoteIp(r *http.Request) string { return strings.Split(r.RemoteAddr, ":")[0] } -func setCorrelationIds(fields logrus.Fields, r *http.Request) { - correlationId := GetCorrelationId(r.Header) +func setCorrelationIds(fields logrus.Fields, h http.Header) { + correlationId := GetCorrelationId(h) if correlationId != "" { fields["correlation_id"] = correlationId } - userCorrelationId := GetUserCorrelationId(r) + userCorrelationId := GetUserCorrelationId(h) if userCorrelationId != "" { fields["user_correlation_id"] = userCorrelationId } diff --git a/logging/logger_test.go b/logging/logger_test.go index c970166..5174a52 100644 --- a/logging/logger_test.go +++ b/logging/logger_test.go @@ -194,14 +194,13 @@ func Test_Logger_Application(t *testing.T) { // given: UserCorrelationCookie = "user_id" - r, _ := http.NewRequest("GET", "http://www.example.org/foo?q=bar", nil) - r.Header = http.Header{ + header := http.Header{ CorrelationIdHeader: {"correlation-123"}, "Cookie": {"user_id=user-id-xyz;"}, } // when: - entry := Application(r) + entry := Application(header) // then: a.Equal("correlation-123", entry.Data["correlation_id"]) diff --git a/util/cookie.go b/util/cookie.go new file mode 100644 index 0000000..f7c18e8 --- /dev/null +++ b/util/cookie.go @@ -0,0 +1,38 @@ +package util + +import ( + "net/http" + "strings" +) + +// taken and adapted from net/http +func ReadCookieValue(h http.Header, cookieName string) (string, bool) { + lines, ok := h["Cookie"] + if !ok { + return "", false + } + + for _, line := range lines { + parts := strings.Split(strings.TrimSpace(line), ";") + if len(parts) == 1 && parts[0] == "" { + continue + } + for i := 0; i < len(parts); i++ { + parts[i] = strings.TrimSpace(parts[i]) + if len(parts[i]) == 0 { + continue + } + name, val := parts[i], "" + if j := strings.Index(name, "="); j >= 0 { + name, val = name[:j], name[j+1:] + } + if cookieName == name { + if len(val) > 1 && val[0] == '"' && val[len(val)-1] == '"' { + val = val[1 : len(val)-1] + } + return val, true + } + } + } + return "", false +} diff --git a/util/cookie_test.go b/util/cookie_test.go new file mode 100644 index 0000000..1562e06 --- /dev/null +++ b/util/cookie_test.go @@ -0,0 +1,32 @@ +package util + +import ( + "github.com/stretchr/testify/assert" + "net/http" + "testing" +) + +func Test_CacheStrategy_readCookieValue(t *testing.T) { + a := assert.New(t) + + v, found := ReadCookieValue(http.Header{"Cookie": {"foo=bar"}}, "foo") + a.True(found) + a.Equal("bar", v) + + v, found = ReadCookieValue(http.Header{"Cookie": {`foo="bar"`}}, "foo") + a.True(found) + a.Equal("bar", v) + + v, found = ReadCookieValue(http.Header{"Cookie": {"foo"}}, "foo") + a.True(found) + a.Equal("", v) + + v, found = ReadCookieValue(http.Header{"Cookie": {";"}}, "foo") + a.False(found) + + v, found = ReadCookieValue(http.Header{"Cookie": {""}}, "foo") + a.False(found) + + v, found = ReadCookieValue(http.Header{}, "foo") + a.False(found) +}