From d0e8c0f7442d7e5d581363231e9e29641c318070 Mon Sep 17 00:00:00 2001 From: Zbigniew Kostrzewa Date: Tue, 19 Jun 2018 22:23:56 +0200 Subject: [PATCH 1/5] Use log timestamps from docker logs. --- router/pump.go | 21 ++++++++++++++++++--- 1 file changed, 18 insertions(+), 3 deletions(-) diff --git a/router/pump.go b/router/pump.go index 6bc14bb9..e95ab54a 100644 --- a/router/pump.go +++ b/router/pump.go @@ -212,7 +212,7 @@ func (p *LogsPump) pumpLogs(event *docker.APIEvents, backlog bool, inactivityTim // RawTerminal with container Tty=false injects binary headers into // the log stream that show up as garbage unicode characters - rawTerminal := false + rawTerminal := false if allowTTY && container.Config.Tty { rawTerminal = true } @@ -235,6 +235,7 @@ func (p *LogsPump) pumpLogs(event *docker.APIEvents, backlog bool, inactivityTim Since: sinceTime.Unix(), InactivityTimeout: inactivityTimeout, RawTerminal: rawTerminal, + Timestamps: true, }) if err != nil { debug("pump.pumpLogs():", id, "stopped with error:", err) @@ -361,10 +362,15 @@ func newContainerPump(container *docker.Container, stdout, stderr io.Reader) *co } return } + logMessage, logTime, err := parseLogLine(line) + if err != nil { + debug("pump.newContainerPump():", normalID(container.ID), ", failed to parse log line:", err) + continue + } cp.send(&Message{ - Data: strings.TrimSuffix(line, "\n"), + Data: logMessage, Container: container, - Time: time.Now(), + Time: logTime, Source: source, }) } @@ -396,3 +402,12 @@ func (cp *containerPump) remove(logstream chan *Message) { defer cp.Unlock() delete(cp.logstreams, logstream) } + +func parseLogLine(line string) (string, time.Time, error) { + logEntry := strings.SplitN(strings.TrimSuffix(line, "\n"), " ", 2) + logTime, err := time.Parse(time.RFC3339Nano, logEntry[0]) + if err != nil { + return "", time.Time{}, err + } + return logEntry[1], logTime, nil +} From 0caaeeef542947a115ec9d190d065c6a921d4c8d Mon Sep 17 00:00:00 2001 From: Zbigniew Kostrzewa Date: Fri, 21 Sep 2018 22:09:37 +0200 Subject: [PATCH 2/5] Apply review remarks. --- CHANGELOG.md | 1 + README.md | 1 + router/pump.go | 30 ++++++++++++++++++++---------- 3 files changed, 22 insertions(+), 10 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 69cf1d0f..96b0dfe1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,7 @@ All notable changes to this project will be documented in this file. - @gbolo added option to harden the TLS client - @chopmann added option to bind the http server to an address - @ibrokethecloud added ability to add custom key:value pairs as EXCLUDE_LABEL. +- @localghost added option to read original logs timestamps from containers ### Removed diff --git a/README.md b/README.md index c827d6c2..a54baac0 100644 --- a/README.md +++ b/README.md @@ -187,6 +187,7 @@ If you use multiline logging with raw, it's recommended to json encode the Data * `MULTILINE_PATTERN` - pattern for multiline logging, see: [MULTILINE_MATCH](#multiline_match) (default: `^\s`) * `MULTILINE_FLUSH_AFTER` - maximum time between the first and last lines of a multiline log entry in milliseconds (default: 500) * `MULTILINE_SEPARATOR` - separator between lines for output (default: `\n`) +* `ORIGINAL_TIMESTAMPS` - read original log timestamps from containers (default: generate timestamps as the logs are processed by logspout) #### Raw Format diff --git a/router/pump.go b/router/pump.go index 81cd528d..4216b057 100644 --- a/router/pump.go +++ b/router/pump.go @@ -33,6 +33,10 @@ func getopt(name, dfault string) string { return value } +func originalTimestamps() bool { + return getopt("ORIGINAL_TIMESTAMPS", "false") == "true" +} + func debug(v ...interface{}) { if os.Getenv("DEBUG") != "" { log.Println(v...) @@ -244,7 +248,7 @@ func (p *LogsPump) pumpLogs(event *docker.APIEvents, backlog bool, inactivityTim Since: sinceTime.Unix(), InactivityTimeout: inactivityTimeout, RawTerminal: rawTerminal, - Timestamps: true, + Timestamps: originalTimestamps(), }) if err != nil { debug("pump.pumpLogs():", id, "stopped with error:", err) @@ -371,11 +375,7 @@ func newContainerPump(container *docker.Container, stdout, stderr io.Reader) *co } return } - logMessage, logTime, err := parseLogLine(line) - if err != nil { - debug("pump.newContainerPump():", normalID(container.ID), ", failed to parse log line:", err) - continue - } + logMessage, logTime := parseLogLine(line, originalTimestamps()) cp.send(&Message{ Data: logMessage, Container: container, @@ -412,11 +412,21 @@ func (cp *containerPump) remove(logstream chan *Message) { delete(cp.logstreams, logstream) } -func parseLogLine(line string) (string, time.Time, error) { - logEntry := strings.SplitN(strings.TrimSuffix(line, "\n"), " ", 2) +func parseLogLine(line string, originalTimestamps bool) (string, time.Time) { + line = strings.TrimSuffix(line, "\n") + + if ! originalTimestamps { + return line, time.Now() + } + + logEntry := strings.SplitN(line, " ", 2) logTime, err := time.Parse(time.RFC3339Nano, logEntry[0]) if err != nil { - return "", time.Time{}, err + return line, time.Now() + } + + if len(logEntry) == 2 { + return logEntry[1], logTime } - return logEntry[1], logTime, nil + return "", logTime } From f00a3c2d86c7dd84336556322ffeb8982a0b2c7b Mon Sep 17 00:00:00 2001 From: Zbigniew Kostrzewa Date: Mon, 22 Oct 2018 20:59:25 +0200 Subject: [PATCH 3/5] Add tests. --- router/pump_test.go | 44 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/router/pump_test.go b/router/pump_test.go index e05f9f99..19f19cb2 100644 --- a/router/pump_test.go +++ b/router/pump_test.go @@ -3,12 +3,14 @@ package router import ( "bytes" "encoding/json" + "fmt" "io/ioutil" "log" "net" "net/http" "os" "testing" + "time" docker "github.com/fsouza/go-dockerclient" ) @@ -229,3 +231,45 @@ func TestPumpRoutingFrom(t *testing.T) { t.Errorf("expected RoutingFrom to return 'false'") } } + +func TestParseLogLine(t *testing.T) { + checkMessage := func(expectedMessage, actualMessage string) { + if actualMessage != expectedMessage { + t.Errorf("Expected message '%s' but got '%s'", expectedMessage, actualMessage) + } + } + + checkEqual := func(expectedMessage, actualMessage string, expectedTime, actualTime time.Time) { + if !actualTime.Equal(expectedTime) { + t.Errorf("Expected time %s but got %s", expectedTime, actualTime) + } + checkMessage(expectedMessage, actualMessage) + } + + checkAfter := func(expectedMessage, actualMessage string, expectedTime, actualTime time.Time) { + if !actualTime.After(expectedTime) { + t.Errorf("Expected actual time %s to be greater than %s", actualTime, expectedTime) + } + checkMessage(expectedMessage, actualMessage) + } + + originalTime := time.Now().Add(-time.Hour) + + actualMessage, actualTime := parseLogLine(fmt.Sprintf("%s Hello world!", originalTime.Format(time.RFC3339Nano)), true) + checkEqual("Hello world!", actualMessage, originalTime, actualTime) + + actualMessage, actualTime = parseLogLine(fmt.Sprintf("%s ", originalTime.Format(time.RFC3339Nano)), true) + checkEqual(" ", actualMessage, originalTime, actualTime) + + actualMessage, actualTime = parseLogLine(originalTime.Format(time.RFC3339Nano), true) + checkEqual("", actualMessage, originalTime, actualTime) + + actualMessage, _ = parseLogLine("Hello world!", true) + checkMessage("Hello world!", actualMessage) + + actualMessage, _ = parseLogLine("Hello world!", false) + checkMessage("Hello world!", actualMessage) + + actualMessage, actualTime = parseLogLine(fmt.Sprintf("%s Hello world!", originalTime.Format(time.RFC3339Nano)), false) + checkAfter(fmt.Sprintf("%s Hello world!", originalTime.Format(time.RFC3339Nano)), actualMessage, originalTime, actualTime) +} From 18772e01bef3d35f46e1869d2561649b1672fd29 Mon Sep 17 00:00:00 2001 From: Zbigniew Kostrzewa Date: Wed, 24 Oct 2018 06:24:24 +0200 Subject: [PATCH 4/5] Change golint repo. --- Makefile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Makefile b/Makefile index 645b9ef7..43974373 100644 --- a/Makefile +++ b/Makefile @@ -38,7 +38,7 @@ build-custom: cd custom && docker build -t $(NAME):custom . lint: - test -x $(GOPATH)/bin/golint || go get github.com/golang/lint/golint + test -x $(GOPATH)/bin/golint || go get golang.org/x/lint/golint go get \ && go install $(GOPACKAGES) \ && go tool vet -v $(shell ls -d */ | egrep -v 'custom|vendor/' | xargs $(XARGS_ARG)) From a783720b9d12724088976c6c1f80ae14c951c27a Mon Sep 17 00:00:00 2001 From: Zbigniew Kostrzewa Date: Wed, 24 Oct 2018 06:27:54 +0200 Subject: [PATCH 5/5] Change golint repo in Circle CI config file. --- circle.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/circle.yml b/circle.yml index 9626e440..622a0da2 100644 --- a/circle.yml +++ b/circle.yml @@ -8,7 +8,7 @@ jobs: steps: - checkout - run: | - go get github.com/golang/lint/golint + go get golang.org/x/lint/golint - run: | make circleci - run: |