transport correlation in all logs

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
 	}

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.

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 ""

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
 	}

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"])

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
+}

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)
+}