From e7fb2058276aec5cb9c8f77fb32fcba10f878e63 Mon Sep 17 00:00:00 2001 From: Marco Pracucci Date: Wed, 31 Jul 2019 19:18:46 +0200 Subject: [PATCH] fix(logcli): timestamp timezone handling (#821) Logcli used to inconsistently handle timezones in timestamps. This addresses this by adding a new `--timezone` / `-z` flag, to explicitly set the timezone the timestamps shall be formatted in. Furthermore it refactors the output framework inside of logcli to test it easier. Fixes #798 --- cmd/logcli/main.go | 20 ++++- cmd/logcli/output.go | 73 ---------------- cmd/logcli/query.go | 28 +++--- cmd/logcli/tail.go | 6 +- cmd/logcli/utils.go | 10 --- pkg/logcli/output/default.go | 36 ++++++++ pkg/logcli/output/default_test.go | 136 ++++++++++++++++++++++++++++++ pkg/logcli/output/jsonl.go | 34 ++++++++ pkg/logcli/output/jsonl_test.go | 80 ++++++++++++++++++ pkg/logcli/output/output.go | 43 ++++++++++ pkg/logcli/output/output_test.go | 28 ++++++ pkg/logcli/output/raw.go | 17 ++++ pkg/logcli/output/raw_test.go | 55 ++++++++++++ 13 files changed, 469 insertions(+), 97 deletions(-) delete mode 100644 cmd/logcli/output.go create mode 100644 pkg/logcli/output/default.go create mode 100644 pkg/logcli/output/default_test.go create mode 100644 pkg/logcli/output/jsonl.go create mode 100644 pkg/logcli/output/jsonl_test.go create mode 100644 pkg/logcli/output/output.go create mode 100644 pkg/logcli/output/output_test.go create mode 100644 pkg/logcli/output/raw.go create mode 100644 pkg/logcli/output/raw_test.go diff --git a/cmd/logcli/main.go b/cmd/logcli/main.go index 38ce7791f7..7ab7c443e5 100644 --- a/cmd/logcli/main.go +++ b/cmd/logcli/main.go @@ -3,7 +3,9 @@ package main import ( "log" "os" + "time" + "github.com/grafana/loki/pkg/logcli/output" "gopkg.in/alecthomas/kingpin.v2" ) @@ -11,6 +13,7 @@ var ( app = kingpin.New("logcli", "A command-line for loki.") quiet = app.Flag("quiet", "suppress everything but log lines").Default("false").Short('q').Bool() outputMode = app.Flag("output", "specify output mode [default, raw, jsonl]").Default("default").Short('o').Enum("default", "raw", "jsonl") + timezone = app.Flag("timezone", "Specify the timezone to use when formatting output timestamps [Local, UTC]").Default("Local").Short('z').Enum("Local", "UTC") addr = app.Flag("addr", "Server address.").Default("https://logs-us-west1.grafana.net").Envar("GRAFANA_ADDR").String() @@ -51,7 +54,22 @@ func main() { switch cmd { case queryCmd.FullCommand(): - doQuery() + location, err := time.LoadLocation(*timezone) + if err != nil { + log.Fatalf("Unable to load timezone '%s': %s", *timezone, err) + } + + outputOptions := &output.LogOutputOptions{ + Timezone: location, + NoLabels: *noLabels, + } + + out, err := output.NewLogOutput(*outputMode, outputOptions) + if err != nil { + log.Fatalf("Unable to create log output: %s", err) + } + + doQuery(out) case labelsCmd.FullCommand(): doLabels() } diff --git a/cmd/logcli/output.go b/cmd/logcli/output.go deleted file mode 100644 index d822775058..0000000000 --- a/cmd/logcli/output.go +++ /dev/null @@ -1,73 +0,0 @@ -package main - -import ( - "encoding/json" - "fmt" - "log" - "strings" - "time" - - "github.com/fatih/color" - "github.com/prometheus/prometheus/pkg/labels" -) - -// Outputs is an enum with all possible output modes -var Outputs = map[string]LogOutput{ - "default": &DefaultOutput{}, - "jsonl": &JSONLOutput{}, - "raw": &RawOutput{}, -} - -// LogOutput is the interface any output mode must implement -type LogOutput interface { - Print(ts time.Time, lbls *labels.Labels, line string) -} - -// DefaultOutput provides logs and metadata in human readable format -type DefaultOutput struct { - MaxLabelsLen int - CommonLabels labels.Labels -} - -// Print a log entry in a human readable format -func (f DefaultOutput) Print(ts time.Time, lbls *labels.Labels, line string) { - ls := subtract(*lbls, f.CommonLabels) - if len(*ignoreLabelsKey) > 0 { - ls = ls.MatchLabels(false, *ignoreLabelsKey...) - } - - labels := "" - if !*noLabels { - labels = padLabel(ls, f.MaxLabelsLen) - } - fmt.Println( - color.BlueString(ts.Format(time.RFC3339)), - color.RedString(labels), - strings.TrimSpace(line), - ) -} - -// JSONLOutput prints logs and metadata as JSON Lines, suitable for scripts -type JSONLOutput struct{} - -// Print a log entry as json line -func (f JSONLOutput) Print(ts time.Time, lbls *labels.Labels, line string) { - entry := map[string]interface{}{ - "timestamp": ts, - "labels": lbls, - "line": line, - } - out, err := json.Marshal(entry) - if err != nil { - log.Fatalf("error marshalling entry: %s", err) - } - fmt.Println(string(out)) -} - -// RawOutput prints logs in their original form, without any metadata -type RawOutput struct{} - -// Print a log entry as is -func (f RawOutput) Print(ts time.Time, lbls *labels.Labels, line string) { - fmt.Println(line) -} diff --git a/cmd/logcli/query.go b/cmd/logcli/query.go index 735527ea40..a6b6c611a0 100644 --- a/cmd/logcli/query.go +++ b/cmd/logcli/query.go @@ -1,6 +1,7 @@ package main import ( + "fmt" "log" "strings" "time" @@ -9,6 +10,7 @@ import ( "github.com/prometheus/prometheus/pkg/labels" "github.com/grafana/loki/pkg/iter" + "github.com/grafana/loki/pkg/logcli/output" "github.com/grafana/loki/pkg/logproto" ) @@ -24,9 +26,9 @@ func getStart(end time.Time) time.Time { return start } -func doQuery() { +func doQuery(out output.LogOutput) { if *tail { - tailQuery() + tailQuery(out) return } @@ -77,13 +79,22 @@ func doQuery() { log.Println("Ignoring labels key:", color.RedString(strings.Join(*ignoreLabelsKey, ","))) } - // Get the max size of labels + // Remove ignored and common labels from the cached labels and + // calculate the max labels length maxLabelsLen := *fixedLabelsLen - for _, ls := range cache { - ls = subtract(common, ls) + for key, ls := range cache { + // Remove common labels + ls = subtract(ls, common) + + // Remove ignored labels if len(*ignoreLabelsKey) > 0 { ls = ls.MatchLabels(false, *ignoreLabelsKey...) } + + // Update cached labels + cache[key] = ls + + // Update max labels length len := len(ls.String()) if maxLabelsLen < len { maxLabelsLen = len @@ -92,14 +103,9 @@ func doQuery() { i = iter.NewQueryResponseIterator(resp, d) - Outputs["default"] = DefaultOutput{ - MaxLabelsLen: maxLabelsLen, - CommonLabels: common, - } - for i.Next() { ls := labelsCache(i.Labels()) - Outputs[*outputMode].Print(i.Entry().Timestamp, &ls, i.Entry().Line) + fmt.Println(out.Format(i.Entry().Timestamp, &ls, maxLabelsLen, i.Entry().Line)) } if err := i.Error(); err != nil { diff --git a/cmd/logcli/tail.go b/cmd/logcli/tail.go index 94ee75b343..5f8057c29e 100644 --- a/cmd/logcli/tail.go +++ b/cmd/logcli/tail.go @@ -1,15 +1,17 @@ package main import ( + "fmt" "log" "strings" + "github.com/grafana/loki/pkg/logcli/output" "github.com/grafana/loki/pkg/querier" "github.com/fatih/color" ) -func tailQuery() { +func tailQuery(out output.LogOutput) { conn, err := liveTailQueryConn() if err != nil { log.Fatalf("Tailing logs failed: %+v", err) @@ -58,7 +60,7 @@ func tailQuery() { for _, entry := range stream.Entries { lbls := mustParseLabels(labels) - Outputs[*outputMode].Print(entry.Timestamp, &lbls, entry.Line) + fmt.Println(out.Format(entry.Timestamp, &lbls, 0, entry.Line)) } } diff --git a/cmd/logcli/utils.go b/cmd/logcli/utils.go index 6054f86ff6..f4093517b6 100644 --- a/cmd/logcli/utils.go +++ b/cmd/logcli/utils.go @@ -3,22 +3,12 @@ package main import ( "log" "sort" - "strings" "github.com/grafana/loki/pkg/logproto" "github.com/prometheus/prometheus/pkg/labels" "github.com/prometheus/prometheus/promql" ) -// add some padding after labels -func padLabel(ls labels.Labels, maxLabelsLen int) string { - labels := ls.String() - if len(labels) < maxLabelsLen { - labels += strings.Repeat(" ", maxLabelsLen-len(labels)) - } - return labels -} - // parse labels from string func mustParseLabels(labels string) labels.Labels { ls, err := promql.ParseMetric(labels) diff --git a/pkg/logcli/output/default.go b/pkg/logcli/output/default.go new file mode 100644 index 0000000000..6dae0c491f --- /dev/null +++ b/pkg/logcli/output/default.go @@ -0,0 +1,36 @@ +package output + +import ( + "fmt" + "strings" + "time" + + "github.com/fatih/color" + "github.com/prometheus/prometheus/pkg/labels" +) + +// DefaultOutput provides logs and metadata in human readable format +type DefaultOutput struct { + options *LogOutputOptions +} + +// Format a log entry in a human readable format +func (o *DefaultOutput) Format(ts time.Time, lbls *labels.Labels, maxLabelsLen int, line string) string { + timestamp := ts.In(o.options.Timezone).Format(time.RFC3339) + line = strings.TrimSpace(line) + + if o.options.NoLabels { + return fmt.Sprintf("%s %s", color.BlueString(timestamp), line) + } + + return fmt.Sprintf("%s %s %s", color.BlueString(timestamp), color.RedString(padLabel(*lbls, maxLabelsLen)), line) +} + +// add some padding after labels +func padLabel(ls labels.Labels, maxLabelsLen int) string { + labels := ls.String() + if len(labels) < maxLabelsLen { + labels += strings.Repeat(" ", maxLabelsLen-len(labels)) + } + return labels +} diff --git a/pkg/logcli/output/default_test.go b/pkg/logcli/output/default_test.go new file mode 100644 index 0000000000..0d6c6104bb --- /dev/null +++ b/pkg/logcli/output/default_test.go @@ -0,0 +1,136 @@ +package output + +import ( + "strings" + "testing" + "time" + + "github.com/prometheus/prometheus/pkg/labels" + "github.com/stretchr/testify/assert" +) + +func TestDefaultOutput_Format(t *testing.T) { + t.Parallel() + + timestamp, _ := time.Parse(time.RFC3339, "2006-01-02T15:04:05+07:00") + emptyLabels := labels.New() + someLabels := labels.New(labels.Label{Name: "type", Value: "test"}) + + tests := map[string]struct { + options *LogOutputOptions + timestamp time.Time + lbls *labels.Labels + maxLabelsLen int + line string + expected string + }{ + "empty line with no labels": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &emptyLabels, + 0, + "", + "2006-01-02T08:04:05Z {} ", + }, + "empty line with labels": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &someLabels, + len(someLabels.String()), + "", + "2006-01-02T08:04:05Z {type=\"test\"} ", + }, + "max labels length shorter than input labels": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &someLabels, + 0, + "Hello", + "2006-01-02T08:04:05Z {type=\"test\"} Hello", + }, + "max labels length longer than input labels": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &someLabels, + 20, + "Hello", + "2006-01-02T08:04:05Z {type=\"test\"} Hello", + }, + "timezone option set to a Local one": { + &LogOutputOptions{Timezone: time.FixedZone("test", 2*60*60), NoLabels: false}, + timestamp, + &someLabels, + 0, + "Hello", + "2006-01-02T10:04:05+02:00 {type=\"test\"} Hello", + }, + "labels output disabled": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: true}, + timestamp, + &someLabels, + 0, + "Hello", + "2006-01-02T08:04:05Z Hello", + }, + } + + for testName, testData := range tests { + testData := testData + + t.Run(testName, func(t *testing.T) { + t.Parallel() + + out := &DefaultOutput{testData.options} + actual := out.Format(testData.timestamp, testData.lbls, testData.maxLabelsLen, testData.line) + + assert.Equal(t, testData.expected, actual) + }) + } +} + +func TestDefaultOutput_FormatLabelsPadding(t *testing.T) { + t.Parallel() + + // Define a list of labels that - once formatted - have a different length + labelsList := []labels.Labels{ + labels.New(labels.Label{Name: "type", Value: "test"}), + labels.New(labels.Label{Name: "type", Value: "test"}, labels.Label{Name: "foo", Value: "bar"}), + labels.New(labels.Label{Name: "type", Value: "a-longer-test"}), + } + + timestamp, _ := time.Parse(time.RFC3339, "2006-01-02T15:04:05+07:00") + maxLabelsLen := findMaxLabelsLength(labelsList) + options := &LogOutputOptions{Timezone: time.UTC, NoLabels: false} + out := &DefaultOutput{options} + + // Format the same log line with different labels + formattedEntries := make([]string, 0, len(labelsList)) + for _, lbls := range labelsList { + formattedEntries = append(formattedEntries, out.Format(timestamp, &lbls, maxLabelsLen, "XXX")) + } + + // Ensure the log line starts at the same position in each formatted output + assert.Equal(t, len(formattedEntries), len(labelsList)) + + expectedIndex := strings.Index(formattedEntries[0], "XXX") + if expectedIndex <= 0 { + assert.FailNowf(t, "Unexpected starting position for log line in the formatted output", "position: %d", expectedIndex) + } + + for _, entry := range formattedEntries { + assert.Equal(t, expectedIndex, strings.Index(entry, "XXX")) + } +} + +func findMaxLabelsLength(labelsList []labels.Labels) int { + maxLabelsLen := 0 + + for _, lbls := range labelsList { + len := len(lbls.String()) + if maxLabelsLen < len { + maxLabelsLen = len + } + } + + return maxLabelsLen +} diff --git a/pkg/logcli/output/jsonl.go b/pkg/logcli/output/jsonl.go new file mode 100644 index 0000000000..37fe2fc8a8 --- /dev/null +++ b/pkg/logcli/output/jsonl.go @@ -0,0 +1,34 @@ +package output + +import ( + "encoding/json" + "log" + "time" + + "github.com/prometheus/prometheus/pkg/labels" +) + +// JSONLOutput prints logs and metadata as JSON Lines, suitable for scripts +type JSONLOutput struct { + options *LogOutputOptions +} + +// Format a log entry as json line +func (o *JSONLOutput) Format(ts time.Time, lbls *labels.Labels, maxLabelsLen int, line string) string { + entry := map[string]interface{}{ + "timestamp": ts.In(o.options.Timezone), + "line": line, + } + + // Labels are optional + if !o.options.NoLabels { + entry["labels"] = lbls + } + + out, err := json.Marshal(entry) + if err != nil { + log.Fatalf("error marshalling entry: %s", err) + } + + return string(out) +} diff --git a/pkg/logcli/output/jsonl_test.go b/pkg/logcli/output/jsonl_test.go new file mode 100644 index 0000000000..d529d5ba77 --- /dev/null +++ b/pkg/logcli/output/jsonl_test.go @@ -0,0 +1,80 @@ +package output + +import ( + "encoding/json" + "testing" + "time" + + "github.com/prometheus/prometheus/pkg/labels" + "github.com/stretchr/testify/assert" +) + +func TestJSONLOutput_Format(t *testing.T) { + t.Parallel() + + timestamp, _ := time.Parse(time.RFC3339, "2006-01-02T15:04:05+07:00") + emptyLabels := labels.New() + someLabels := labels.New(labels.Label{Name: "type", Value: "test"}) + + tests := map[string]struct { + options *LogOutputOptions + timestamp time.Time + lbls *labels.Labels + maxLabelsLen int + line string + expected string + }{ + "empty line with no labels": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &emptyLabels, + 0, + "", + `{"labels":{},"line":"","timestamp":"2006-01-02T08:04:05Z"}`, + }, + "empty line with labels": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &someLabels, + len(someLabels.String()), + "", + `{"labels":{"type":"test"},"line":"","timestamp":"2006-01-02T08:04:05Z"}`, + }, + "timezone option set to a Local one": { + &LogOutputOptions{Timezone: time.FixedZone("test", 2*60*60), NoLabels: false}, + timestamp, + &someLabels, + 0, + "Hello", + `{"labels":{"type":"test"},"line":"Hello","timestamp":"2006-01-02T10:04:05+02:00"}`, + }, + "labels output disabled": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: true}, + timestamp, + &someLabels, + 0, + "Hello", + `{"line":"Hello","timestamp":"2006-01-02T08:04:05Z"}`, + }, + } + + for testName, testData := range tests { + testData := testData + + t.Run(testName, func(t *testing.T) { + t.Parallel() + + out := &JSONLOutput{testData.options} + actual := out.Format(testData.timestamp, testData.lbls, testData.maxLabelsLen, testData.line) + + assert.Equal(t, testData.expected, actual) + assert.NoError(t, isValidJSON(actual)) + }) + } +} + +func isValidJSON(s string) error { + var data map[string]interface{} + + return json.Unmarshal([]byte(s), &data) +} diff --git a/pkg/logcli/output/output.go b/pkg/logcli/output/output.go new file mode 100644 index 0000000000..55b14823bb --- /dev/null +++ b/pkg/logcli/output/output.go @@ -0,0 +1,43 @@ +package output + +import ( + "fmt" + "time" + + "github.com/prometheus/prometheus/pkg/labels" +) + +// LogOutput is the interface any output mode must implement +type LogOutput interface { + Format(ts time.Time, lbls *labels.Labels, maxLabelsLen int, line string) string +} + +// LogOutputOptions defines options supported by LogOutput +type LogOutputOptions struct { + Timezone *time.Location + NoLabels bool +} + +// NewLogOutput creates a log output based on the input mode and options +func NewLogOutput(mode string, options *LogOutputOptions) (LogOutput, error) { + if options.Timezone == nil { + options.Timezone = time.Local + } + + switch mode { + case "default": + return &DefaultOutput{ + options: options, + }, nil + case "jsonl": + return &JSONLOutput{ + options: options, + }, nil + case "raw": + return &RawOutput{ + options: options, + }, nil + default: + return nil, fmt.Errorf("unknown log output mode '%s'", mode) + } +} diff --git a/pkg/logcli/output/output_test.go b/pkg/logcli/output/output_test.go new file mode 100644 index 0000000000..4e57211d05 --- /dev/null +++ b/pkg/logcli/output/output_test.go @@ -0,0 +1,28 @@ +package output + +import ( + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestNewLogOutput(t *testing.T) { + options := &LogOutputOptions{time.UTC, false} + + out, err := NewLogOutput("default", options) + assert.NoError(t, err) + assert.IsType(t, &DefaultOutput{options}, out) + + out, err = NewLogOutput("jsonl", options) + assert.NoError(t, err) + assert.IsType(t, &JSONLOutput{options}, out) + + out, err = NewLogOutput("raw", options) + assert.NoError(t, err) + assert.IsType(t, &RawOutput{options}, out) + + out, err = NewLogOutput("unknown", options) + assert.Error(t, err) + assert.Nil(t, out) +} diff --git a/pkg/logcli/output/raw.go b/pkg/logcli/output/raw.go new file mode 100644 index 0000000000..a05e43b248 --- /dev/null +++ b/pkg/logcli/output/raw.go @@ -0,0 +1,17 @@ +package output + +import ( + "time" + + "github.com/prometheus/prometheus/pkg/labels" +) + +// RawOutput prints logs in their original form, without any metadata +type RawOutput struct { + options *LogOutputOptions +} + +// Format a log entry as is +func (o *RawOutput) Format(ts time.Time, lbls *labels.Labels, maxLabelsLen int, line string) string { + return line +} diff --git a/pkg/logcli/output/raw_test.go b/pkg/logcli/output/raw_test.go new file mode 100644 index 0000000000..96d27fdcc0 --- /dev/null +++ b/pkg/logcli/output/raw_test.go @@ -0,0 +1,55 @@ +package output + +import ( + "testing" + "time" + + "github.com/prometheus/prometheus/pkg/labels" + "github.com/stretchr/testify/assert" +) + +func TestRawOutput_Format(t *testing.T) { + t.Parallel() + + timestamp, _ := time.Parse(time.RFC3339, "2006-01-02T15:04:05+07:00") + someLabels := labels.New(labels.Label{Name: "type", Value: "test"}) + + tests := map[string]struct { + options *LogOutputOptions + timestamp time.Time + lbls *labels.Labels + maxLabelsLen int + line string + expected string + }{ + "empty line": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &someLabels, + 0, + "", + "", + }, + "non empty line": { + &LogOutputOptions{Timezone: time.UTC, NoLabels: false}, + timestamp, + &someLabels, + 0, + "Hello world", + "Hello world", + }, + } + + for testName, testData := range tests { + testData := testData + + t.Run(testName, func(t *testing.T) { + t.Parallel() + + out := &RawOutput{testData.options} + actual := out.Format(testData.timestamp, testData.lbls, testData.maxLabelsLen, testData.line) + + assert.Equal(t, testData.expected, actual) + }) + } +}