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

@@ -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()
 	}

cmd/logcli/output.go

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

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 {

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

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)

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

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

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

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

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

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

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

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