commit 91b029ebe1c523eb48f4b4f27d6740f1253a1891
parent 7492300307ee18fd46b6df2575429d292bc72c9c
Author: Sebastian Mancke <s.mancke@tarent.de>
Date: Mon, 22 May 2017 22:13:02 +0200
internalized logging dependencies
Diffstat:
13 files changed, 968 insertions(+), 6 deletions(-)
diff --git a/caddy/setup.go b/caddy/setup.go
@@ -5,7 +5,7 @@ import (
"fmt"
"github.com/mholt/caddy"
"github.com/mholt/caddy/caddyhttp/httpserver"
- "github.com/tarent/lib-compose/logging"
+ "github.com/tarent/loginsrv/logging"
"github.com/tarent/loginsrv/login"
"os"
"path"
diff --git a/logging/correlation_id.go b/logging/correlation_id.go
@@ -0,0 +1,51 @@
+package logging
+
+import (
+ "github.com/tarent/lib-compose/util"
+ "math/rand"
+ "net/http"
+ "time"
+)
+
+const letterBytes = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789"
+
+func init() {
+ rand.Seed(time.Now().UTC().UnixNano())
+}
+
+var CorrelationIdHeader = "X-Correlation-Id"
+var UserCorrelationCookie = ""
+
+// EnsureCorrelationId returns the correlation from of the request.
+// If the request does not have a correlation id, one will be generated and set to the request.
+func EnsureCorrelationId(r *http.Request) string {
+ id := r.Header.Get(CorrelationIdHeader)
+ if id == "" {
+ id = randStringBytes(10)
+ r.Header.Set(CorrelationIdHeader, id)
+ }
+ return id
+}
+
+// GetCorrelationId returns the correlation from of the request.
+func GetCorrelationId(h http.Header) string {
+ return h.Get(CorrelationIdHeader)
+}
+
+func randStringBytes(n int) string {
+ b := make([]byte, n)
+ for i := range b {
+ b[i] = letterBytes[rand.Intn(len(letterBytes))]
+ }
+ return string(b)
+}
+
+// GetCorrelationId returns the users correlation id of the headers.
+func GetUserCorrelationId(h http.Header) string {
+ if UserCorrelationCookie != "" {
+ if value, found := util.ReadCookieValue(h, UserCorrelationCookie); found {
+ return value
+ }
+ }
+ return ""
+}
diff --git a/logging/log_middleware.go b/logging/log_middleware.go
@@ -0,0 +1,82 @@
+package logging
+
+import (
+ "fmt"
+ "net/http"
+ "runtime"
+ "strings"
+ "time"
+)
+
+type LogMiddleware struct {
+ Next http.Handler
+}
+
+func NewLogMiddleware(next http.Handler) *LogMiddleware {
+ return &LogMiddleware{
+ Next: next,
+ }
+}
+
+func (mw *LogMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+ EnsureCorrelationId(r)
+ start := time.Now()
+
+ defer func() {
+ if rec := recover(); rec != nil {
+ AccessError(r, start, fmt.Errorf("PANIC (%v): %v", identifyLogOrigin(), rec))
+ }
+ }()
+
+ lrw := &logResponseWriter{ResponseWriter: w}
+ mw.Next.ServeHTTP(lrw, r)
+
+ Access(r, start, lrw.statusCode)
+}
+
+// identifyLogOrigin returns the location, where a panic was raised
+// in the form package/subpackage.method:line
+func identifyLogOrigin() string {
+ var name, file string
+ var line int
+ var pc [16]uintptr
+
+ n := runtime.Callers(3, pc[:])
+ for _, pc := range pc[:n] {
+ fn := runtime.FuncForPC(pc)
+ if fn == nil {
+ continue
+ }
+ file, line = fn.FileLine(pc)
+ name = fn.Name()
+ if !strings.HasPrefix(name, "runtime.") {
+ break
+ }
+ }
+
+ switch {
+ case name != "":
+ return fmt.Sprintf("%v:%v", name, line)
+ case file != "":
+ return fmt.Sprintf("%v:%v", file, line)
+ }
+
+ return fmt.Sprintf("pc:%x", pc)
+}
+
+type logResponseWriter struct {
+ http.ResponseWriter
+ statusCode int
+}
+
+func (lrw *logResponseWriter) Write(b []byte) (int, error) {
+ if lrw.statusCode == 0 {
+ lrw.statusCode = 200
+ }
+ return lrw.ResponseWriter.Write(b)
+}
+
+func (lrw *logResponseWriter) WriteHeader(statusCode int) {
+ lrw.statusCode = statusCode
+ lrw.ResponseWriter.WriteHeader(statusCode)
+}
diff --git a/logging/log_middleware_test.go b/logging/log_middleware_test.go
@@ -0,0 +1,79 @@
+package logging
+
+import (
+ "bytes"
+ "github.com/stretchr/testify/assert"
+ "net/http"
+ "net/http/httptest"
+ "testing"
+)
+
+func Test_LogMiddleware_Panic(t *testing.T) {
+ a := assert.New(t)
+
+ // given: a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // and a handler which raises a panic
+ lm := NewLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+ i := []int{}
+ i[100]++
+ }))
+
+ r, _ := http.NewRequest("GET", "http://www.example.org/foo", nil)
+
+ lm.ServeHTTP(httptest.NewRecorder(), r)
+
+ data := logRecordFromBuffer(b)
+ a.Contains(data.Error, "logging.Test_LogMiddleware_Panic.func1")
+ a.Contains(data.Error, "runtime error: index out of range")
+ a.Contains(data.Message, "ERROR ->GET /foo")
+ a.Equal(data.Level, "error")
+}
+
+func Test_LogMiddleware_Log_implicit200(t *testing.T) {
+ a := assert.New(t)
+
+ // given: a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // and a handler which gets an 200er code implicitly
+ lm := NewLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+ w.Write([]byte("hello"))
+ }))
+
+ r, _ := http.NewRequest("GET", "http://www.example.org/foo", nil)
+
+ lm.ServeHTTP(httptest.NewRecorder(), r)
+
+ data := logRecordFromBuffer(b)
+ a.Equal("", data.Error)
+ a.Equal("200 ->GET /foo", data.Message)
+ a.Equal(200, data.ResponseStatus)
+ a.Equal("info", data.Level)
+}
+
+func Test_LogMiddleware_Log_404(t *testing.T) {
+ a := assert.New(t)
+
+ // given: a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // and a handler which gets an 404er code explicitly
+ lm := NewLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+ w.WriteHeader(404)
+ }))
+
+ r, _ := http.NewRequest("GET", "http://www.example.org/foo", nil)
+
+ lm.ServeHTTP(httptest.NewRecorder(), r)
+
+ data := logRecordFromBuffer(b)
+ a.Equal("", data.Error)
+ a.Equal("404 ->GET /foo", data.Message)
+ a.Equal(404, data.ResponseStatus)
+ a.Equal("warning", data.Level)
+}
diff --git a/logging/logger.go b/logging/logger.go
@@ -0,0 +1,253 @@
+package logging
+
+import (
+ "encoding/json"
+ "fmt"
+ "github.com/tarent/logrus"
+ "net/http"
+ "os"
+ "strings"
+ "time"
+)
+
+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)
+}
+
+// Set creates a new Logger with the matching specification
+func Set(level string, textLogging bool) error {
+ l, err := logrus.ParseLevel(level)
+ if err != nil {
+ return err
+ }
+
+ logger := logrus.New()
+ if textLogging {
+ logger.Formatter = &logrus.TextFormatter{}
+ } else {
+ logger.Formatter = &LogstashFormatter{TimestampFormat: time.RFC3339Nano}
+ }
+ logger.Level = l
+ Logger = logger
+ return nil
+}
+
+// Access logs an access entry with call duration and status code
+func Access(r *http.Request, start time.Time, statusCode int) {
+ e := access(r, start, statusCode, nil)
+
+ var msg string
+ if len(r.URL.RawQuery) == 0 {
+ msg = fmt.Sprintf("%v ->%v %v", statusCode, r.Method, r.URL.Path)
+ } else {
+ msg = fmt.Sprintf("%v ->%v %v?...", statusCode, r.Method, r.URL.Path)
+ }
+
+ if statusCode >= 200 && statusCode <= 399 {
+ e.Info(msg)
+ } else if statusCode >= 400 && statusCode <= 499 {
+ e.Warn(msg)
+ } else {
+ e.Error(msg)
+ }
+}
+
+// AccessError logs an error while accessing
+func AccessError(r *http.Request, start time.Time, err error) {
+ e := access(r, start, 0, err)
+ e.Errorf("ERROR ->%v %v", r.Method, r.URL.Path)
+}
+
+func access(r *http.Request, start time.Time, statusCode int, err error) *logrus.Entry {
+ url := r.URL.Path
+ if r.URL.RawQuery != "" {
+ url += "?" + r.URL.RawQuery
+ }
+ fields := logrus.Fields{
+ "type": "access",
+ "@timestamp": start,
+ "remote_ip": getRemoteIp(r),
+ "host": r.Host,
+ "url": url,
+ "method": r.Method,
+ "proto": r.Proto,
+ "duration": time.Since(start).Nanoseconds() / 1000000,
+ "User_Agent": r.Header.Get("User-Agent"),
+ }
+
+ if statusCode != 0 {
+ fields["response_status"] = statusCode
+ }
+
+ if err != nil {
+ fields[logrus.ErrorKey] = err.Error()
+ }
+
+ setCorrelationIds(fields, r.Header)
+
+ cookies := map[string]string{}
+ for _, c := range r.Cookies() {
+ if !contains(AccessLogCookiesBlacklist, c.Name) {
+ cookies[c.Name] = c.Value
+ }
+ }
+ if len(cookies) > 0 {
+ fields["cookies"] = cookies
+ }
+
+ return Logger.WithFields(fields)
+}
+
+// Call logs the result of an outgoing call
+func Call(r *http.Request, resp *http.Response, start time.Time, err error) {
+ url := r.URL.Path
+ if r.URL.RawQuery != "" {
+ url += "?" + r.URL.RawQuery
+ }
+ fields := logrus.Fields{
+ "type": "call",
+ "@timestamp": start,
+ "host": r.Host,
+ "url": url,
+ "full_url": r.URL.String(),
+ "method": r.Method,
+ "duration": time.Since(start).Nanoseconds() / 1000000,
+ }
+
+ setCorrelationIds(fields, r.Header)
+
+ if err != nil {
+ fields[logrus.ErrorKey] = err.Error()
+ Logger.WithFields(fields).Error(err)
+ return
+ }
+
+ if resp != nil {
+ fields["response_status"] = resp.StatusCode
+ fields["content_type"] = resp.Header.Get("Content-Type")
+ e := Logger.WithFields(fields)
+ msg := fmt.Sprintf("%v %v-> %v", resp.StatusCode, r.Method, r.URL.String())
+
+ if resp.StatusCode >= 200 && resp.StatusCode <= 399 {
+ e.Info(msg)
+ } else if resp.StatusCode >= 400 && resp.StatusCode <= 499 {
+ e.Warn(msg)
+ } else {
+ e.Error(msg)
+ }
+ return
+ }
+
+ Logger.WithFields(fields).Warn("call, but no response given")
+}
+
+// Cacheinfo logs the hit information a accessing a ressource
+func Cacheinfo(url string, hit bool) {
+ var msg string
+ if hit {
+ msg = fmt.Sprintf("cache hit: %v", url)
+ } else {
+ msg = fmt.Sprintf("cache miss: %v", url)
+ }
+ Logger.WithFields(
+ logrus.Fields{
+ "type": "cacheinfo",
+ "url": url,
+ "hit": hit,
+ }).
+ Debug(msg)
+}
+
+// Return a log entry for application logs,
+// prefilled with the correlation ids out of the supplied request.
+func Application(h http.Header) *logrus.Entry {
+ fields := logrus.Fields{
+ "type": "application",
+ }
+ setCorrelationIds(fields, h)
+ return Logger.WithFields(fields)
+}
+
+// LifecycleStart logs the start of an application
+// with the configuration struct or map as paramter.
+func LifecycleStart(appName string, args interface{}) {
+ fields := logrus.Fields{}
+
+ jsonString, err := json.Marshal(args)
+ if err == nil {
+ err := json.Unmarshal(jsonString, &fields)
+ if err != nil {
+ fields["parse_error"] = err.Error()
+ }
+ }
+ fields["type"] = "lifecycle"
+ fields["event"] = "start"
+ for _, env := range LifecycleEnvVars {
+ if os.Getenv(env) != "" {
+ fields[strings.ToLower(env)] = os.Getenv(env)
+ }
+ }
+
+ Logger.WithFields(fields).Infof("starting application: %v", appName)
+}
+
+// LifecycleStop logs the stop of an application
+func LifecycleStop(appName string, signal os.Signal, err error) {
+ fields := logrus.Fields{
+ "type": "lifecycle",
+ "event": "stop",
+ }
+ if signal != nil {
+ fields["signal"] = signal.String()
+ }
+
+ if os.Getenv("BUILD_NUMBER") != "" {
+ fields["build_number"] = os.Getenv("BUILD_NUMBER")
+ }
+
+ if err != nil {
+ Logger.WithFields(fields).
+ WithError(err).
+ Errorf("stopping application: %v (%v)", appName, err)
+ } else {
+ Logger.WithFields(fields).Infof("stopping application: %v (%v)", appName, signal)
+ }
+}
+
+func getRemoteIp(r *http.Request) string {
+ if r.Header.Get("X-Cluster-Client-Ip") != "" {
+ return r.Header.Get("X-Cluster-Client-Ip")
+ }
+ if r.Header.Get("X-Real-Ip") != "" {
+ return r.Header.Get("X-Real-Ip")
+ }
+ return strings.Split(r.RemoteAddr, ":")[0]
+}
+
+func setCorrelationIds(fields logrus.Fields, h http.Header) {
+ correlationId := GetCorrelationId(h)
+ if correlationId != "" {
+ fields["correlation_id"] = correlationId
+ }
+
+ userCorrelationId := GetUserCorrelationId(h)
+ if userCorrelationId != "" {
+ fields["user_correlation_id"] = userCorrelationId
+ }
+}
+
+func contains(s []string, e string) bool {
+ for _, a := range s {
+ if a == e {
+ return true
+ }
+ }
+ return false
+}
diff --git a/logging/logger_test.go b/logging/logger_test.go
@@ -0,0 +1,337 @@
+package logging
+
+import (
+ "bytes"
+ "encoding/json"
+ "errors"
+ "github.com/tarent/logrus"
+ "github.com/stretchr/testify/assert"
+ "net/http"
+ "os"
+ "testing"
+ "time"
+)
+
+type logReccord struct {
+ Type string `json:"type"`
+ Timestamp string `json:"@timestamp"`
+ CorrelationId string `json:"correlation_id"`
+ RemoteIp string `json:"remote_ip"`
+ Host string `json:"host"`
+ URL string `json:"url"`
+ Method string `json:"method"`
+ Proto string `json:"proto"`
+ Duration int `json:"duration"`
+ ResponseStatus int `json:"response_status"`
+ UserCorrelationId string `json:"user_correlation_id"`
+ Cookies map[string]string `json:"cookies"`
+ Error string `json:"error"`
+ Message string `json:"message"`
+ Level string `json:"level"`
+ UserAgent string `json:"User_Agent"`
+}
+
+func Test_Logger_Set(t *testing.T) {
+ a := assert.New(t)
+
+ // given: an error logger in text format
+ Set("error", true)
+ defer Set("info", false)
+ Logger.Formatter.(*logrus.TextFormatter).DisableColors = true
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // when: I log something
+ Logger.Info("should be ignored ..")
+ Logger.WithField("foo", "bar").Error("oops")
+
+ // then: only the error text is contained
+ // and it is text formated
+ a.Regexp(`^time.* level\=error msg\=oops foo\=bar.*`, b.String())
+}
+
+func Test_Logger_Call(t *testing.T) {
+ a := assert.New(t)
+
+ // given a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+ AccessLogCookiesBlacklist = []string{"ignore", "user_id"}
+ UserCorrelationCookie = "user_id"
+
+ // and a request
+ r, _ := http.NewRequest("GET", "http://www.example.org/foo?q=bar", nil)
+ r.Header = http.Header{
+ CorrelationIdHeader: {"correlation-123"},
+ "Cookie": {"user_id=user-id-xyz; ignore=me; foo=bar;"},
+ }
+
+ resp := &http.Response{
+ StatusCode: 404,
+ Header: http.Header{"Content-Type": {"text/html"}},
+ }
+
+ // when: We log a request with access
+ start := time.Now().Add(-1 * time.Second)
+ Call(r, resp, start, nil)
+
+ // then: all fields match
+ data := &logReccord{}
+ err := json.Unmarshal(b.Bytes(), data)
+ a.NoError(err)
+
+ a.Equal("warning", data.Level)
+ a.Equal("correlation-123", data.CorrelationId)
+ a.Equal("user-id-xyz", data.UserCorrelationId)
+ a.InDelta(1000, data.Duration, 0.5)
+ a.Equal("", data.Error)
+ a.Equal("www.example.org", data.Host)
+ a.Equal("GET", data.Method)
+ a.Equal("404 GET-> http://www.example.org/foo?q=bar", data.Message)
+ a.Equal(404, data.ResponseStatus)
+ a.Equal("call", data.Type)
+ a.Equal("/foo?q=bar", data.URL)
+
+ // when we call with an error
+ b.Reset()
+ start = time.Now().Add(-1 * time.Second)
+ Call(r, nil, start, errors.New("oops"))
+
+ // then: all fields match
+ data = &logReccord{}
+ err = json.Unmarshal(b.Bytes(), data)
+ a.NoError(err)
+
+ a.Equal("error", data.Level)
+ a.Equal("oops", data.Error)
+ a.Equal("oops", data.Message)
+ a.Equal("correlation-123", data.CorrelationId)
+ a.Equal("user-id-xyz", data.UserCorrelationId)
+ a.InDelta(1000, data.Duration, 0.5)
+ a.Equal("www.example.org", data.Host)
+ a.Equal("GET", data.Method)
+ a.Equal("call", data.Type)
+ a.Equal("/foo?q=bar", data.URL)
+}
+
+func Test_Logger_Access(t *testing.T) {
+ a := assert.New(t)
+
+ // given a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+ AccessLogCookiesBlacklist = []string{"ignore", "user_id"}
+ UserCorrelationCookie = "user_id"
+
+ // Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.84 Safari/537.36
+
+ // and a request
+ r, _ := http.NewRequest("GET", "http://www.example.org/foo?q=bar", nil)
+ r.Header = http.Header{
+ CorrelationIdHeader: {"correlation-123"},
+ "Cookie": {"user_id=user-id-xyz; ignore=me; foo=bar;"},
+ "User-Agent": {"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.84 Safari/537.36"},
+ }
+ r.RemoteAddr = "127.0.0.1"
+
+ // when: We log a request with access
+ start := time.Now().Add(-1 * time.Second)
+ Access(r, start, 201)
+
+ // then: all fields match
+ data := &logReccord{}
+ err := json.Unmarshal(b.Bytes(), data)
+ a.NoError(err)
+
+ a.Equal("info", data.Level)
+ a.Equal(map[string]string{"foo": "bar"}, data.Cookies)
+ a.Equal("correlation-123", data.CorrelationId)
+ a.InDelta(1000, data.Duration, 0.5)
+ a.Equal("", data.Error)
+ a.Equal("www.example.org", data.Host)
+ a.Equal("GET", data.Method)
+ a.Equal("HTTP/1.1", data.Proto)
+ a.Equal("201 ->GET /foo?...", data.Message)
+ a.Equal("127.0.0.1", data.RemoteIp)
+ a.Equal(201, data.ResponseStatus)
+ a.Equal("access", data.Type)
+ a.Equal("/foo?q=bar", data.URL)
+ a.Equal("user-id-xyz", data.UserCorrelationId)
+ a.Equal("Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.84 Safari/537.36", data.UserAgent)
+}
+
+func Test_Logger_Access_ErrorCases(t *testing.T) {
+ a := assert.New(t)
+
+ // given a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // and a request
+ r, _ := http.NewRequest("GET", "http://www.example.org/foo", nil)
+
+ // when a status 404 is logged
+ Access(r, time.Now(), 404)
+ // then: all fields match
+ data := logRecordFromBuffer(b)
+ a.Equal("warning", data.Level)
+ a.Equal("404 ->GET /foo", data.Message)
+
+ // when a status 500 is logged
+ b.Reset()
+ Access(r, time.Now(), 500)
+ // then: all fields match
+ data = logRecordFromBuffer(b)
+ a.Equal("error", data.Level)
+
+ // when an error is logged
+ b.Reset()
+ AccessError(r, time.Now(), errors.New("oops"))
+ // then: all fields match
+ data = logRecordFromBuffer(b)
+ a.Equal("error", data.Level)
+ a.Equal("oops", data.Error)
+ a.Equal("ERROR ->GET /foo", data.Message)
+}
+
+func Test_Logger_Application(t *testing.T) {
+ a := assert.New(t)
+
+ // given:
+ UserCorrelationCookie = "user_id"
+ header := http.Header{
+ CorrelationIdHeader: {"correlation-123"},
+ "Cookie": {"user_id=user-id-xyz;"},
+ }
+
+ // when:
+ entry := Application(header)
+
+ // then:
+ a.Equal("correlation-123", entry.Data["correlation_id"])
+ a.Equal("user-id-xyz", entry.Data["user_correlation_id"])
+}
+
+func Test_Logger_LifecycleStart(t *testing.T) {
+ a := assert.New(t)
+
+ // given a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // and
+ someArguments := struct {
+ Foo string
+ Number int
+ }{
+ Foo: "bar",
+ Number: 42,
+ }
+
+ // and an Environment Variable with the Build Number is set
+ os.Setenv("BUILD_NUMBER", "b666")
+
+ // when a LifecycleStart is logged
+ LifecycleStart("my-app", someArguments)
+
+ // then: it is logged
+ data := mapFromBuffer(b)
+ a.Equal("info", data["level"])
+ a.Equal("lifecycle", data["type"])
+ a.Equal("start", data["event"])
+ a.Equal("bar", data["Foo"])
+ a.Equal(42.0, data["Number"])
+ a.Equal("b666", data["build_number"])
+}
+
+func Test_Logger_LifecycleStop(t *testing.T) {
+ a := assert.New(t)
+
+ // given a logger
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // and an Environment Variable with the Build Number is set
+ os.Setenv("BUILD_NUMBER", "b666")
+
+ // when a LifecycleStart is logged
+ LifecycleStop("my-app", os.Interrupt, nil)
+
+ // then: it is logged
+ data := mapFromBuffer(b)
+ a.Equal("info", data["level"])
+ a.Equal("stopping application: my-app (interrupt)", data["message"])
+ a.Equal("lifecycle", data["type"])
+ a.Equal("stop", data["event"])
+ a.Equal("interrupt", data["signal"])
+ a.Equal("b666", data["build_number"])
+}
+
+func Test_Logger_Cacheinfo(t *testing.T) {
+ a := assert.New(t)
+
+ // given a logger
+ Set("debug", false)
+ defer Set("info", false)
+ b := bytes.NewBuffer(nil)
+ Logger.Out = b
+
+ // when a positive cachinfo is logged
+ Cacheinfo("/foo", true)
+
+ // then: it is logged
+ data := mapFromBuffer(b)
+ a.Equal("/foo", data["url"])
+ a.Equal("cacheinfo", data["type"])
+ a.Equal(true, data["hit"])
+ a.Equal("cache hit: /foo", data["message"])
+
+ b.Reset()
+ // logging a non hit
+ Cacheinfo("/foo", false)
+ data = mapFromBuffer(b)
+ a.Equal(false, data["hit"])
+ a.Equal("cache miss: /foo", data["message"])
+}
+
+func Test_Logger_GetRemoteIp1(t *testing.T) {
+ a := assert.New(t)
+ req, _ := http.NewRequest("GET", "test.com", nil)
+ req.Header["X-Cluster-Client-Ip"] = []string {"1234"}
+ ret := getRemoteIp(req)
+ a.Equal("1234", ret)
+}
+
+func Test_Logger_GetRemoteIp2(t *testing.T) {
+ a := assert.New(t)
+ req, _ := http.NewRequest("GET", "test.com", nil)
+ req.Header["X-Real-Ip"] = []string {"1234"}
+ ret := getRemoteIp(req)
+ a.Equal("1234", ret)
+}
+
+func Test_Logger_GetRemoteIp3(t *testing.T) {
+ a := assert.New(t)
+ req, _ := http.NewRequest("GET", "test.com", nil)
+ req.RemoteAddr = "1234:80"
+ ret := getRemoteIp(req)
+ a.Equal("1234", ret)
+}
+
+func logRecordFromBuffer(b *bytes.Buffer) *logReccord {
+ data := &logReccord{}
+ err := json.Unmarshal(b.Bytes(), data)
+ if err != nil {
+ panic(err.Error() + " " + b.String())
+ }
+ return data
+}
+
+func mapFromBuffer(b *bytes.Buffer) map[string]interface{} {
+ data := map[string]interface{}{}
+ err := json.Unmarshal(b.Bytes(), &data)
+ if err != nil {
+ panic(err.Error() + " " + b.String())
+ }
+ return data
+}
diff --git a/logging/logstash_formatter.go b/logging/logstash_formatter.go
@@ -0,0 +1,84 @@
+package logging
+
+import (
+ "encoding/json"
+ "fmt"
+ "strings"
+
+ "github.com/tarent/logrus"
+)
+
+// Taken from github.com/bshuster-repo/logrus-logstash-hook
+// MIT License (MIT)
+// Copyright (c) 2016 Boaz Shuster
+
+// Formatter generates json in logstash format.
+// Logstash site: http://logstash.net/
+type LogstashFormatter struct {
+ Type string // if not empty use for logstash type field.
+
+ // TimestampFormat sets the format used for timestamps.
+ TimestampFormat string
+}
+
+func (f *LogstashFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+ return f.FormatWithPrefix(entry, "")
+}
+
+func (f *LogstashFormatter) FormatWithPrefix(entry *logrus.Entry, prefix string) ([]byte, error) {
+ fields := make(logrus.Fields)
+ for k, v := range entry.Data {
+ //remvove the prefix when sending the fields to logstash
+ if prefix != "" && strings.HasPrefix(k, prefix) {
+ k = strings.TrimPrefix(k, prefix)
+ }
+
+ switch v := v.(type) {
+ case error:
+ // Otherwise errors are ignored by `encoding/json`
+ // https://github.com/Sirupsen/logrus/issues/377
+ fields[k] = v.Error()
+ default:
+ fields[k] = v
+ }
+ }
+
+ fields["@version"] = "1"
+
+ timeStampFormat := f.TimestampFormat
+
+ if timeStampFormat == "" {
+ timeStampFormat = logrus.DefaultTimestampFormat
+ }
+
+ fields["@timestamp"] = entry.Time.Format(timeStampFormat)
+
+ // set message field
+ v, ok := entry.Data["message"]
+ if ok {
+ fields["fields.message"] = v
+ }
+ fields["message"] = entry.Message
+
+ // set level field
+ v, ok = entry.Data["level"]
+ if ok {
+ fields["fields.level"] = v
+ }
+ fields["level"] = entry.Level.String()
+
+ // set type field
+ if f.Type != "" {
+ v, ok = entry.Data["type"]
+ if ok {
+ fields["fields.type"] = v
+ }
+ fields["type"] = f.Type
+ }
+
+ serialized, err := json.Marshal(fields)
+ if err != nil {
+ return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)
+ }
+ return append(serialized, '\n'), nil
+}
diff --git a/logging/logstash_formatter_test.go b/logging/logstash_formatter_test.go
@@ -0,0 +1,76 @@
+package logging
+
+import (
+ "bytes"
+ "encoding/json"
+ "fmt"
+ "net/url"
+ "testing"
+
+ "github.com/tarent/logrus"
+)
+
+// Taken from github.com/bshuster-repo/logrus-logstash-hook
+// MIT License (MIT)
+// Copyright (c) 2016 Boaz Shuster
+
+func TestLogstashFormatter(t *testing.T) {
+ lf := LogstashFormatter{Type: "abc"}
+
+ fields := logrus.Fields{
+ "message": "def",
+ "level": "ijk",
+ "type": "lmn",
+ "one": 1,
+ "pi": 3.14,
+ "bool": true,
+ "error": &url.Error{Op: "Get", URL: "http://example.com", Err: fmt.Errorf("The error")},
+ }
+
+ entry := logrus.WithFields(fields)
+ entry.Message = "msg"
+ entry.Level = logrus.InfoLevel
+
+ b, _ := lf.Format(entry)
+
+ var data map[string]interface{}
+ dec := json.NewDecoder(bytes.NewReader(b))
+ dec.UseNumber()
+ dec.Decode(&data)
+
+ // base fields
+ if data["@timestamp"] == "" {
+ t.Error("expected @timestamp to be not empty")
+ }
+ tt := []struct {
+ expected string
+ key string
+ }{
+ // base fields
+ {"1", "@version"},
+ {"abc", "type"},
+ {"msg", "message"},
+ {"info", "level"},
+ {"Get http://example.com: The error", "error"},
+ // substituted fields
+ {"def", "fields.message"},
+ {"ijk", "fields.level"},
+ {"lmn", "fields.type"},
+ }
+ for _, te := range tt {
+ if te.expected != data[te.key] {
+ t.Errorf("expected data[%s] to be '%s' but got '%s'", te.key, te.expected, data[te.key])
+ }
+ }
+
+ // formats
+ if json.Number("1") != data["one"] {
+ t.Errorf("expected one to be '%v' but got '%v'", json.Number("1"), data["one"])
+ }
+ if json.Number("3.14") != data["pi"] {
+ t.Errorf("expected pi to be '%v' but got '%v'", json.Number("3.14"), data["pi"])
+ }
+ if true != data["bool"] {
+ t.Errorf("expected bool to be '%v' but got '%v'", true, data["bool"])
+ }
+}
diff --git a/login/config.go b/login/config.go
@@ -4,7 +4,7 @@ import (
"errors"
"flag"
"fmt"
- "github.com/tarent/lib-compose/logging"
+ "github.com/tarent/loginsrv/logging"
"github.com/tarent/loginsrv/oauth2"
"math/rand"
"os"
diff --git a/login/handler.go b/login/handler.go
@@ -5,7 +5,7 @@ import (
"errors"
"fmt"
"github.com/dgrijalva/jwt-go"
- "github.com/tarent/lib-compose/logging"
+ "github.com/tarent/loginsrv/logging"
"github.com/tarent/loginsrv/model"
"github.com/tarent/loginsrv/oauth2"
"io/ioutil"
diff --git a/login/login_form.go b/login/login_form.go
@@ -2,7 +2,7 @@ package login
import (
"bytes"
- "github.com/tarent/lib-compose/logging"
+ "github.com/tarent/loginsrv/logging"
"github.com/tarent/loginsrv/model"
"html/template"
"io/ioutil"
diff --git a/main.go b/main.go
@@ -6,7 +6,7 @@ import (
"github.com/tarent/loginsrv/login"
- "github.com/tarent/lib-compose/logging"
+ "github.com/tarent/loginsrv/logging"
"net/http"
"os"
"os/signal"
diff --git a/osiam/setup.go b/osiam/setup.go
@@ -1,7 +1,7 @@
package osiam
import (
- "github.com/tarent/lib-compose/logging"
+ "github.com/tarent/loginsrv/logging"
"github.com/tarent/loginsrv/login"
)