fix tests

e2e_test.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"context"
 	"encoding/json"
-	"io/ioutil"
 	"os"
 	"path/filepath"
 	"testing"
@@ -27,15 +26,15 @@ func TestHarness(t *testing.T) {
 		}
 		testCase := de.Name()
 		t.Run(testCase, func(t *testing.T) {
-			input, err := ioutil.ReadFile(filepath.Join(root, de.Name(), "input"))
+			input, err := os.ReadFile(filepath.Join(root, de.Name(), "input"))
 			if err != nil {
 				t.Fatalf("reading input: %v", err)
 			}
-			want, err := ioutil.ReadFile(filepath.Join(root, de.Name(), "want"))
+			want, err := os.ReadFile(filepath.Join(root, de.Name(), "want"))
 			if err != nil {
 				t.Fatalf("reading expected output: %v", err)
 			}
-			cfgjson, err := ioutil.ReadFile(filepath.Join(root, de.Name(), "config.json"))
+			cfgjson, err := os.ReadFile(filepath.Join(root, de.Name(), "config.json"))
 			if err != nil {
 				t.Fatalf("reading config: %v", err)
 			}
@@ -45,7 +44,7 @@ func TestHarness(t *testing.T) {
 			}
 			gotw := bytes.NewBuffer(nil)
 			sinkOpts, errs := stdiosink.StdioOptsFrom(cfg)
-			if len(errs) > 1 {
+			if len(errs) > 0 {
 				t.Fatalf("errs=%v", errs)
 			}
 			s := stdiosink.NewStdio(gotw, sinkOpts)
@@ -87,11 +86,11 @@ func TestHarness(t *testing.T) {
 				t.Errorf("got  %q", gotPart)
 			}
 
-			dir, err := ioutil.TempDir(os.TempDir(), "humanlog-tests-*")
+			dir, err := os.MkdirTemp(os.TempDir(), "humanlog-tests-*")
 			if err != nil {
 				t.Fatal(err)
 			}
-			gotf, err := ioutil.TempFile(dir, de.Name())
+			gotf, err := os.CreateTemp(dir, de.Name())
 			if err != nil {
 				t.Fatal(err)
 			}

handler.go

@@ -1,6 +1,8 @@
 package humanlog
 
 import (
+	"time"
+
 	"github.com/humanlogio/humanlog/internal/pkg/config"
 	"github.com/kr/logfmt"
 )
@@ -17,6 +19,7 @@ var DefaultOptions = func() *HandlerOptions {
 		TimeFields:    []string{"time", "ts", "@timestamp", "timestamp", "Timestamp"},
 		MessageFields: []string{"message", "msg", "Body"},
 		LevelFields:   []string{"level", "lvl", "loglevel", "severity", "SeverityText"},
+		timeNow:       time.Now,
 	}
 	return opts
 }
@@ -25,6 +28,8 @@ type HandlerOptions struct {
 	TimeFields    []string
 	MessageFields []string
 	LevelFields   []string
+
+	timeNow func() time.Time
 }
 
 var _ = HandlerOptionsFrom(config.DefaultConfig) // ensure it's valid

internal/pkg/config/config.go

@@ -89,6 +89,7 @@ type Config struct {
 	ColorMode           *string      `json:"color-mode"`
 	TruncateLength      *int         `json:"truncate-length"`
 	TimeFormat          *string      `json:"time-format"`
+	TimeZone            *string      `json:"time-zone"`
 	Palette             *TextPalette `json:"palette"`
 	Interrupt           *bool        `json:"interrupt"`
 	SkipCheckForUpdates *bool        `json:"skip_check_updates"`
@@ -148,6 +149,9 @@ func (cfg Config) populateEmpty(other *Config) *Config {
 	if out.TimeFormat == nil && other.TimeFormat != nil {
 		out.TimeFormat = other.TimeFormat
 	}
+	if out.TimeZone == nil && other.TimeZone != nil {
+		out.TimeZone = other.TimeZone
+	}
 	if out.Palette == nil && other.Palette != nil {
 		out.Palette = other.Palette
 	}
@@ -157,6 +161,9 @@ func (cfg Config) populateEmpty(other *Config) *Config {
 	if out.SkipCheckForUpdates == nil && other.SkipCheckForUpdates != nil {
 		out.SkipCheckForUpdates = other.SkipCheckForUpdates
 	}
+	if out.ExperimentalFeatures == nil && other.ExperimentalFeatures != nil {
+		out.ExperimentalFeatures = other.ExperimentalFeatures
+	}
 	return &out
 }
 

pkg/sink/stdiosink/stdio.go

@@ -35,6 +35,7 @@ type StdioOpts struct {
 	SkipUnchanged  bool
 	SortLongest    bool
 	TimeFormat     string
+	TimeZone       *time.Location
 	TruncateLength int
 	Truncates      bool
 
@@ -48,6 +49,7 @@ var DefaultStdioOpts = StdioOpts{
 	SkipUnchanged:  true,
 	SortLongest:    true,
 	TimeFormat:     time.Stamp,
+	TimeZone:       time.Local,
 	TruncateLength: 15,
 	Truncates:      true,
 
@@ -83,6 +85,13 @@ func StdioOptsFrom(cfg config.Config) (StdioOpts, []error) {
 	if cfg.TimeFormat != nil {
 		opts.TimeFormat = *cfg.TimeFormat
 	}
+	if cfg.TimeZone != nil {
+		var err error
+		opts.TimeZone, err = time.LoadLocation(*cfg.TimeZone)
+		if err != nil {
+			errs = append(errs, fmt.Errorf("invalid --time-zone=%q: %v", *cfg.TimeZone, err))
+		}
+	}
 	if cfg.ColorMode != nil {
 		colorMode, err := config.GrokColorMode(*cfg.ColorMode)
 		if err != nil {
@@ -181,9 +190,18 @@ func (std *Stdio) Receive(ctx context.Context, ev *typesv1.LogEvent) error {
 	} else {
 		timeColor = std.opts.Palette.TimeDarkBgColor
 	}
-
+	var timestr string
+	ts := data.Timestamp.AsTime()
+	if ts.IsZero() {
+		timestr = "<no time>"
+	} else {
+		if std.opts.TimeZone != nil {
+			ts = ts.In(std.opts.TimeZone)
+		}
+		timestr = timeColor.Sprint(ts.Format(std.opts.TimeFormat))
+	}
 	_, _ = fmt.Fprintf(out, "%s |%s| %s\t %s",
-		timeColor.Sprint(data.Timestamp.AsTime().Format(std.opts.TimeFormat)),
+		timestr,
 		level,
 		msg,
 		strings.Join(std.joinKVs(data, "="), "\t "),

scanner.go

@@ -38,7 +38,7 @@ func Scan(ctx context.Context, src io.Reader, sink sink.Sink, opts *HandlerOptio
 		}
 		data.Reset()
 		ev.Raw = lineData
-		ev.ParsedAt = timestamppb.Now()
+		ev.ParsedAt = timestamppb.New(opts.timeNow())
 
 		// remove that pesky syslog crap
 		lineData = bytes.TrimPrefix(lineData, []byte("@cee: "))

scanner_test.go

@@ -4,21 +4,52 @@ import (
 	"context"
 	"strings"
 	"testing"
+	"time"
 
 	typesv1 "github.com/humanlogio/api/go/types/v1"
 	"github.com/humanlogio/humanlog/pkg/sink/bufsink"
 	"github.com/stretchr/testify/require"
+	"google.golang.org/protobuf/encoding/protojson"
+	"google.golang.org/protobuf/proto"
+	"google.golang.org/protobuf/types/known/timestamppb"
 )
 
 func TestScannerLongLine(t *testing.T) {
-	data := `{"msg":"` + strings.Repeat("a", 1023*1024) + `"}`
+	data := `{"msg":"` + strings.Repeat("a", 3 /*1023*1024*/) + `"}`
 	ctx := context.Background()
 	src := strings.NewReader(data)
+
+	now := time.Date(2024, 10, 11, 15, 25, 6, 0, time.UTC)
 	want := []*typesv1.LogEvent{
-		{Raw: []byte(data), Structured: &typesv1.StructuredLogEvent{Msg: strings.Repeat("a", 1023*1024)}},
+		{
+			ParsedAt: timestamppb.New(now),
+			Raw:      []byte(data),
+			Structured: &typesv1.StructuredLogEvent{
+				Msg:       strings.Repeat("a", 3 /*1023*1024*/),
+				Timestamp: timestamppb.New(time.Time{}),
+			},
+		},
+	}
+
+	opts := DefaultOptions()
+	opts.timeNow = func() time.Time {
+		return now
 	}
+
 	sink := bufsink.NewSizedBufferedSink(100, nil)
-	err := Scan(ctx, src, sink, DefaultOptions())
+	err := Scan(ctx, src, sink, opts)
 	require.NoError(t, err, "got %#v", err)
-	require.Equal(t, want, sink.Buffered)
+
+	require.Len(t, sink.Buffered, len(want))
+	for i, got := range sink.Buffered {
+		require.Equal(t, pjson(want[i]), pjson(got))
+	}
+}
+
+func pjson(m proto.Message) string {
+	o, err := protojson.Marshal(m)
+	if err != nil {
+		panic(err)
+	}
+	return string(o)
 }

test/cases/00001-json/config.json

@@ -24,6 +24,6 @@
     "color-mode": "off",
     "truncate-length": 15,
     "time-format": "Jan _2 15:04:05",
+    "time-zone": "UTC",
     "palette": null
   }
-

test/cases/00001-json/want

@@ -1,25 +1,25 @@
-Aug 11 13:14:50 || <no msg> specversion="1.0" type="simple-log" invloglevel="Info" id="01FCV6S4M6S8H3VKAQD9SWFWFP" datacontenttype="application/json" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:The login-api service is running on port 8085. short:service-startup]
-Aug 11 13:14:55 || <no msg> invweburl="" invwebbytes=0 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6S9YK70GJ5Q6YT0PYKQDA" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6S9YJXD2SYG3HTGWXHX0G" data=map[message:incoming HTTP request was served short:http access]
-Aug 11 13:14:59 || <no msg> id="01FCV6SDKRW3XZDA1FAGZ3QVSH" invapptracingrequestid="01FCV6SDKRHB1RR1Q87Q1SKT5P"
-Aug 11 13:15:00 || <no msg> id="01FCV6SE597EY6RJ762V59PZQA" invapptracingrequestid="01FCV6SE596ZMASA1D79M16KVV"
-Aug 11 13:15:00 || <no msg> id="01FCV6SEKCC9RG364AJ60J75KW" invapptracingrequestid="01FCV6SEKCNSQJJ2NDEPQ2TGMP"
-Aug 11 13:15:00 || <no msg> id="01FCV6SF3DXGB8G1DVX19KQZYT" invapptracingrequestid="01FCV6SF3DJZSXTT1RNR6F1QAV"
-Aug 11 13:15:05 || <no msg> id="01FCV6SKY9MM7D795258XPQGC9" invapptracingrequestid="01FCV6SKY9M1D725HTV0ZXKF1V"
-Aug 11 13:15:10 || <no msg> type="service-shutdown" data=map[event:Shutdown] id="01FCV6SR6JZH7JZ6RFDFN9Q99Y"
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |DEBU| <no msg> 
-Jan  1 00:00:00 |INFO| <no msg> 
-Jan  1 00:00:00 |WARN| <no msg> 
-Jan  1 00:00:00 |WARN| <no msg> 
-Jan  1 00:00:00 |ERRO| <no msg> 
-Jan  1 00:00:00 |PANI| <no msg> 
-Jan  1 00:00:00 |SOME| <no msg> 
+Aug 11 18:14:50 || <no msg> specversion="1.0" type="simple-log" invloglevel="Info" id="01FCV6S4M6S8H3VKAQD9SWFWFP" datacontenttype="application/json" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:The login-api service is running on port 8085. short:service-startup]
+Aug 11 18:14:55 || <no msg> invweburl="" invwebbytes=0 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6S9YK70GJ5Q6YT0PYKQDA" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6S9YJXD2SYG3HTGWXHX0G" data=map[message:incoming HTTP request was served short:http access]
+Aug 11 18:14:59 || <no msg> id="01FCV6SDKRW3XZDA1FAGZ3QVSH" invapptracingrequestid="01FCV6SDKRHB1RR1Q87Q1SKT5P"
+Aug 11 18:15:00 || <no msg> id="01FCV6SE597EY6RJ762V59PZQA" invapptracingrequestid="01FCV6SE596ZMASA1D79M16KVV"
+Aug 11 18:15:00 || <no msg> id="01FCV6SEKCC9RG364AJ60J75KW" invapptracingrequestid="01FCV6SEKCNSQJJ2NDEPQ2TGMP"
+Aug 11 18:15:00 || <no msg> id="01FCV6SF3DXGB8G1DVX19KQZYT" invapptracingrequestid="01FCV6SF3DJZSXTT1RNR6F1QAV"
+Aug 11 18:15:05 || <no msg> id="01FCV6SKY9MM7D795258XPQGC9" invapptracingrequestid="01FCV6SKY9M1D725HTV0ZXKF1V"
+Aug 11 18:15:10 || <no msg> type="service-shutdown" data=map[event:Shutdown] id="01FCV6SR6JZH7JZ6RFDFN9Q99Y"
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |DEBU| <no msg> 
+<no time> |INFO| <no msg> 
+<no time> |WARN| <no msg> 
+<no time> |WARN| <no msg> 
+<no time> |ERRO| <no msg> 
+<no time> |PANI| <no msg> 
+<no time> |SOME| <no msg> 

test/cases/00002-logfmt/config.json

@@ -24,5 +24,6 @@
   "color-mode": "off",
   "truncate-length": 15,
   "time-format": "Jan _2 15:04:05",
+  "time-zone": "UTC",
   "palette": null
 }

test/cases/00002-logfmt/want

@@ -1,22 +1,22 @@
-Jan  1 00:00:00 || i like turtle key=value1
-Jan  1 00:00:00 || i like turtle key2=42
-Jan  1 00:00:00 || i like turtle key2=43 key=value2
+<no time> || i like turtle key=value1
+<no time> || i like turtle key2=42
+<no time> || i like turtle key2=43 key=value2
 Sep 11 16:31:21 || <no msg> do_all_electric_sheeps=dream
 Sep 11 16:31:21 || <no msg> 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Aug 11 13:15:10 || hello 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |FATA| <no msg> 
-Jan  1 00:00:00 |DEBU| <no msg> 
-Jan  1 00:00:00 |INFO| <no msg> 
-Jan  1 00:00:00 |WARN| <no msg> 
-Jan  1 00:00:00 |WARN| <no msg> 
-Jan  1 00:00:00 |ERRO| <no msg> 
-Jan  1 00:00:00 |PANI| <no msg> 
-Jan  1 00:00:00 |SOME| <no msg> 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+Aug 11 18:15:10 || hello 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |FATA| <no msg> 
+<no time> |DEBU| <no msg> 
+<no time> |INFO| <no msg> 
+<no time> |WARN| <no msg> 
+<no time> |WARN| <no msg> 
+<no time> |ERRO| <no msg> 
+<no time> |PANI| <no msg> 
+<no time> |SOME| <no msg> 

test/cases/00003-zap/config.json

@@ -24,5 +24,6 @@
   "color-mode": "off",
   "truncate-length": 15,
   "time-format": "Jan _2 15:04:05",
+  "time-zone": "UTC",
   "palette": null
 }

test/cases/00003-zap/want

@@ -1,8 +1,8 @@
-Feb  5 12:41:48 |DEBU| some message 1 rand_index=1 caller=zapper/zapper.go:18
-Feb  5 12:41:49 |ERRO| some message 2 rand_index=3 caller=zapper/zapper.go:18
-Feb  5 15:45:04 |FATA| some message 5 rand_index=11 caller=zapper/zapper.go:18
-Feb  5 12:41:50 |INFO| some message 3 rand_index=5 caller=zapper/zapper.go:18
-Feb  5 12:41:51 |WARN| some message 4 rand_index=7 caller=zapper/zapper.go:18
+Feb  5 19:41:48 |DEBU| some message 1 rand_index=1 caller=zapper/zapper.go:18
+Feb  5 19:41:49 |ERRO| some message 2 rand_index=3 caller=zapper/zapper.go:18
+Feb  5 22:45:04 |FATA| some message 5 rand_index=11 caller=zapper/zapper.go:18
+Feb  5 19:41:50 |INFO| some message 3 rand_index=5 caller=zapper/zapper.go:18
+Feb  5 19:41:51 |WARN| some message 4 rand_index=7 caller=zapper/zapper.go:18
 2021-02-06T22:55:22.004Z	DEBUG	zapper/zapper.go:17	some message 1	{"rand_index": 1}
 2021-02-06T22:55:22.008Z	ERROR	zapper/zapper.go:17	some message 2	{"rand_index": 2}
 2021-02-06T22:55:22.009Z	FATAL	zapper/zapper.go:17	some message 5	{"rand_index": 1}

test/cases/00004-mixed/config.json

@@ -24,5 +24,6 @@
   "color-mode": "off",
   "truncate-length": 15,
   "time-format": "Jan _2 15:04:05",
+  "time-zone": "UTC",
   "palette": null
 }

test/cases/00005-otel/config.json

@@ -1,11 +1,11 @@
 {
-    "sort-longest": true,
-    "skip-unchanged": true,
-    "truncates": false,
-    "light-bg": false,
-    "color-mode": "off",
-    "truncate-length": 15,
-    "time-format": "Jan _2 15:04:05",
-    "palette": null
-  }
-  
+  "sort-longest": true,
+  "skip-unchanged": true,
+  "truncates": false,
+  "light-bg": false,
+  "color-mode": "off",
+  "truncate-length": 15,
+  "time-format": "Jan _2 15:04:05",
+  "time-zone": "UTC",
+  "palette": null
+}

test/cases/10000-behavior-base/config.json

@@ -24,5 +24,6 @@
   "color-mode": "off",
   "truncate-length": 15,
   "time-format": "Jan _2 15:04:05",
+  "time-zone": "UTC",
   "palette": null
 }

test/cases/10000-behavior-base/want

@@ -1,4 +1,4 @@
-Jan  1 00:00:00 || <no msg> k1="short" k2="lonnnnnnnnnnnnnnnnnnng"
-Jan  1 00:00:00 || <no msg> repeated="first time"
-Jan  1 00:00:00 || <no msg> 
-Jan  1 00:00:00 || <no msg> repeated="second time"
+<no time> || <no msg> k1="short" k2="lonnnnnnnnnnnnnnnnnnng"
+<no time> || <no msg> repeated="first time"
+<no time> || <no msg> 
+<no time> || <no msg> repeated="second time"