diff --git a/.golangci.yml b/.golangci.yml new file mode 100644 index 0000000..bec87c2 --- /dev/null +++ b/.golangci.yml @@ -0,0 +1,15 @@ +version: "2" + +linters: + settings: + errcheck: + exclude-functions: + - (io.Reader).Read + - (io.Writer).Write + - (io.Closer).Close + - (io.ReadCloser).Close + - (io.WriteCloser).Close + - (bytes.Buffer).ReadFrom + - (bytes.Buffer).WriteTo + - (net/http.ResponseWriter).Write + - fmt.Fprintf diff --git a/internal/example_splunk/main.go b/internal/example_splunk/main.go index f484054..1b2162c 100644 --- a/internal/example_splunk/main.go +++ b/internal/example_splunk/main.go @@ -12,6 +12,7 @@ import ( "github.com/osbuild/logging/pkg/splunk" ) +//nolint:errcheck func main() { srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { buf := new(bytes.Buffer) diff --git a/internal/example_web/main.go b/internal/example_web/main.go index 7d02627..193e3b4 100644 --- a/internal/example_web/main.go +++ b/internal/example_web/main.go @@ -31,6 +31,7 @@ var pairs = []strc.HeaderField{ {HeaderName: "X-Request-Id", FieldName: "request_id"}, } +//nolint:errcheck func startServers(logger *slog.Logger) (*echo.Echo, *echo.Echo) { tracerMW := strc.EchoTraceExtractor() loggerMW := strc.EchoRequestLogger(logger, strc.MiddlewareConfig{}) @@ -86,6 +87,7 @@ func startServers(logger *slog.Logger) (*echo.Echo, *echo.Echo) { return s1, s2 } +//nolint:errcheck func request(req *http.Request, handler slog.Handler) { logger := slog.New(strc.NewMultiHandlerCustom(nil, strc.HeadersCallback(pairs), handler)) slog.SetDefault(logger) diff --git a/pkg/sinit/flush_test.go b/pkg/sinit/flush_test.go index 032ff20..cfed7c1 100644 --- a/pkg/sinit/flush_test.go +++ b/pkg/sinit/flush_test.go @@ -6,6 +6,7 @@ import ( "time" ) +//nolint:errcheck func TestValidationSplunkFlushRacy(t *testing.T) { ctx := context.Background() cfg := LoggingConfig{ diff --git a/pkg/sinit/init_test.go b/pkg/sinit/init_test.go index b6de9f3..16fb18e 100644 --- a/pkg/sinit/init_test.go +++ b/pkg/sinit/init_test.go @@ -112,7 +112,10 @@ func TestValidationSplunkWithHostname(t *testing.T) { }() slog.Warn("foo") - Flush() + err = Flush() + if err != nil { + t.Fatalf("expected no error on flush, got %v", err) + } select { case splunkBody := <-ch: @@ -156,7 +159,10 @@ func TestValidationSplunkWithoutHostname(t *testing.T) { }() slog.Warn("foo") - Flush() + err = Flush() + if err != nil { + t.Fatalf("expected no error on flush, got %v", err) + } select { case splunkBody := <-ch: diff --git a/pkg/splunk/client.go b/pkg/splunk/client.go index 51718cf..b600db7 100644 --- a/pkg/splunk/client.go +++ b/pkg/splunk/client.go @@ -73,7 +73,7 @@ type Stats struct { LastRequestDuration time.Duration } -func newSplunkLogger(ctx context.Context, url, token, source, hostname string, maximumSize int) *splunkLogger { +func newSplunkLogger(ctx context.Context, url, token, source, hostname string, maximumSize int, sendFrequency time.Duration) *splunkLogger { rcl := retryablehttp.NewClient() sl := &splunkLogger{ @@ -84,7 +84,7 @@ func newSplunkLogger(ctx context.Context, url, token, source, hostname string, m hostname: hostname, payloadsChannelSize: DefaultPayloadsChannelSize, maximumSize: DefaultMaximumSize, - sendFrequency: DefaultSendFrequency, + sendFrequency: sendFrequency, pool: sync.Pool{ New: func() any { buf := &bytes.Buffer{} diff --git a/pkg/splunk/client_test.go b/pkg/splunk/client_test.go index 87782bd..8c8aaff 100644 --- a/pkg/splunk/client_test.go +++ b/pkg/splunk/client_test.go @@ -6,7 +6,6 @@ import ( "net/http" "net/http/httptest" "reflect" - "sync" "sync/atomic" "testing" "time" @@ -14,6 +13,8 @@ import ( "github.com/stretchr/testify/assert" ) +const testSendFrequency = 100 * time.Millisecond + func decodeBody(t *testing.T, r *http.Request) map[string]any { m := map[string]any{} err := json.NewDecoder(r.Body).Decode(&m) @@ -25,17 +26,19 @@ func decodeBody(t *testing.T, r *http.Request) map[string]any { } func TestSplunkLoggerRetry(t *testing.T) { - var internalErrorOnce sync.Once + var counter atomic.Int32 ch := make(chan bool) time.AfterFunc(time.Second*8, func() { ch <- false }) srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - internalErrorOnce.Do(func() { - // make sure the logger retries requests + if counter.Load() == 0 { + // make sure the logger retries the request + counter.Add(1) w.WriteHeader(http.StatusInternalServerError) - }) + return + } if r.Header.Get("Authorization") != "Splunk token" { t.Errorf("got %v, want Splunk token", r.Header.Get("Authorization")) } @@ -59,12 +62,17 @@ func TestSplunkLoggerRetry(t *testing.T) { })) defer srv.Close() - sl := newSplunkLogger(context.Background(), srv.URL, "token", "source", "hostname", 0) + sl := newSplunkLogger(context.Background(), srv.URL, "token", "source", "hostname", 0, testSendFrequency) _, err := sl.event([]byte("{}\n")) if err != nil { t.Error(err) } - sl.close(100 * time.Millisecond) + defer func() { + err := sl.close(100 * time.Millisecond) + if err != nil { + t.Error(err) + } + }() if !<-ch { t.Error("timeout") @@ -103,12 +111,17 @@ func TestSplunkLoggerContext(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second*1) defer cancel() - sl := newSplunkLogger(ctx, srv.URL, "token", "source", "hostname", 0) + sl := newSplunkLogger(ctx, srv.URL, "token", "source", "hostname", 0, testSendFrequency) _, err := sl.event([]byte("{}\n")) if err != nil { t.Error(err) } - sl.close(100 * time.Millisecond) + defer func() { + err := sl.close(100 * time.Millisecond) + if err != nil { + t.Error(err) + } + }() if !<-ch { t.Error("timeout") @@ -126,8 +139,13 @@ func TestSplunkLoggerPayloads(t *testing.T) { { name: "empty", f: func() error { - sl := newSplunkLogger(context.Background(), url, "token", "source", "hostname", 0) - defer sl.close(100 * time.Millisecond) + sl := newSplunkLogger(context.Background(), url, "token", "source", "hostname", 0, testSendFrequency) + defer func() { + err := sl.close(100 * time.Millisecond) + if err != nil { + t.Error(err) + } + }() _, err := sl.event([]byte("{}\n")) if err != nil { return err @@ -147,8 +165,13 @@ func TestSplunkLoggerPayloads(t *testing.T) { { name: "json", f: func() error { - sl := newSplunkLogger(context.Background(), url, "token", "source", "hostname", 0) - defer sl.close(100 * time.Millisecond) + sl := newSplunkLogger(context.Background(), url, "token", "source", "hostname", 0, testSendFrequency) + defer func() { + err := sl.close(100 * time.Millisecond) + if err != nil { + t.Error(err) + } + }() _, err := sl.event([]byte(`{"a": "b"}` + "\n")) if err != nil { return err @@ -212,7 +235,7 @@ func TestSplunkLoggerCloseTimeout(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second*1) defer cancel() - sl := newSplunkLogger(ctx, srv.URL, "token", "source", "hostname", 0) + sl := newSplunkLogger(ctx, srv.URL, "token", "source", "hostname", 0, testSendFrequency) _, err := sl.event([]byte("{}\n")) if err != nil { t.Error(err) diff --git a/pkg/splunk/handler.go b/pkg/splunk/handler.go index 331feab..3a156a3 100644 --- a/pkg/splunk/handler.go +++ b/pkg/splunk/handler.go @@ -59,7 +59,7 @@ type SplunkConfig struct { func NewSplunkHandler(ctx context.Context, config SplunkConfig) *SplunkHandler { h := &SplunkHandler{ level: config.Level, - splunk: newSplunkLogger(ctx, config.URL, config.Token, config.Source, config.Hostname, config.DefaultMaximumSize), + splunk: newSplunkLogger(ctx, config.URL, config.Token, config.Source, config.Hostname, config.DefaultMaximumSize, DefaultSendFrequency), } h.jh = slog.NewJSONHandler(h, &slog.HandlerOptions{Level: config.Level, AddSource: true, ReplaceAttr: replaceAttr}) @@ -77,8 +77,8 @@ func (h *SplunkHandler) Flush() { // logs after closing the handler will return ErrFullOrClosed. The call can // block but not longer than 2 seconds. Use CloseWithTimeout to specify a custom // timeout. -func (h *SplunkHandler) Close() { - h.splunk.close(2 * time.Second) +func (h *SplunkHandler) Close() error { + return h.splunk.close(2 * time.Second) } // CloseWithTimeout flushes all pending payloads and closes the Splunk client. diff --git a/pkg/splunk/handler_test.go b/pkg/splunk/handler_test.go index 9cdd0d6..6442e48 100644 --- a/pkg/splunk/handler_test.go +++ b/pkg/splunk/handler_test.go @@ -18,7 +18,7 @@ func TestSplunkHandler(t *testing.T) { emptyLines := 0 srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { buf := new(bytes.Buffer) - buf.ReadFrom(r.Body) + _, _ = buf.ReadFrom(r.Body) lines := strings.Split(buf.String(), "\n") for _, line := range lines { @@ -96,7 +96,10 @@ func TestSplunkHandler(t *testing.T) { h := NewSplunkHandler(context.Background(), c) logger := slog.New(h) tt.f(logger) - h.Close() + err := h.Close() + if err != nil { + t.Error(err) + } stats := h.Statistics() if int(stats.EventCount) != tt.events { @@ -118,7 +121,7 @@ func TestSplunkHandler(t *testing.T) { func TestSplunkHandlerBatching(t *testing.T) { srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { buf := new(bytes.Buffer) - buf.ReadFrom(r.Body) + buf.ReadFrom(r.Body) //nolint:errcheck lines := strings.Split(buf.String(), "\n") for _, line := range lines { @@ -145,7 +148,10 @@ func TestSplunkHandlerBatching(t *testing.T) { for i := 0; i < 4000; i++ { logger.Debug("msg", "i", i) } - h.Close() + err := h.Close() + if err != nil { + t.Error(err) + } stats := h.Statistics() t.Logf("events: %d, batches: %d", stats.EventCount, stats.BatchCount) diff --git a/pkg/strc/README.md b/pkg/strc/README.md index 855d0f2..e60edbd 100644 --- a/pkg/strc/README.md +++ b/pkg/strc/README.md @@ -42,6 +42,16 @@ Spans end up in log sink too, for better readability, the following fields are a * `trace_id` - trace ID (disable by setting `strc.TraceIDFieldKey` to empty string) * `build_id` - build Git sha (disable by setting `strc.BuildIDFieldKey` to empty string) +### Overriding time + +Span start, event and end time is automatically taken via `time.Now()` call but there are some use cases when this needs to be overridden to a specific time. Use special attributes to do that: + +```go +span := strc.Start(ctx, "span name", "started", time.Now()) +span.Event("an event", "at", time.Now()) +span.End("finished", time.Now()) +``` + ### Propagation A simple HTTP header-based propagation API is available. Note this is not meant to be used directly, there is HTTP middleware and client wrapper available: diff --git a/pkg/strc/context_test.go b/pkg/strc/context_test.go index 54bc4c3..50a8b9c 100644 --- a/pkg/strc/context_test.go +++ b/pkg/strc/context_test.go @@ -11,7 +11,7 @@ import ( func TestTraceID(t *testing.T) { src = rand.NewSource(0) var tid TraceID - var r *http.Request = &http.Request{ + r := &http.Request{ Header: http.Header{}, } @@ -62,7 +62,7 @@ func TestTraceID(t *testing.T) { func TestSpanID(t *testing.T) { src = rand.NewSource(0) var sid SpanID - var r *http.Request = &http.Request{ + r := &http.Request{ Header: http.Header{}, } diff --git a/pkg/strc/trace.go b/pkg/strc/trace.go index d913726..0363f4f 100644 --- a/pkg/strc/trace.go +++ b/pkg/strc/trace.go @@ -77,6 +77,8 @@ type Span struct { // // It immediately logs a message with the span name, span information in SpanGroupName and optional // arguments. +// +// Special argument named "started" of type time.Time can be used to set the start time of the span. func Start(ctx context.Context, name string, args ...any) (*Span, context.Context) { return tracer.Load().Start(ctx, name, args...) } @@ -92,6 +94,11 @@ func (t *Tracer) Start(ctx context.Context, name string, args ...any) (*Span, co sid := NewSpanID(ctx) ctx = WithSpanID(ctx, sid) + started := time.Now() + if p := findArgs[time.Time](args, "started"); p != nil { + started = *p + } + span := &Span{ ctx: ctx, tracer: t, @@ -99,7 +106,7 @@ func (t *Tracer) Start(ctx context.Context, name string, args ...any) (*Span, co tid: tid, sid: sid, args: args, - started: time.Now(), + started: started, } if !t.logger.Enabled(ctx, Level) { @@ -135,11 +142,18 @@ func (t *Tracer) Start(ctx context.Context, name string, args ...any) (*Span, co // // It immediately logs a message with the span name, span information in SpanGroupName and // optional arguments. +// +// Special argument named "at" of type time.Time can be used to set the event time. func (s *Span) Event(name string, args ...any) { if !s.tracer.logger.Enabled(s.ctx, Level) { return } + at := time.Now() + if p := findArgs[time.Time](args, "at"); p != nil { + at = *p + } + // keep the order and capacity correct attrs := make([]slog.Attr, 0, 6+1) attrs = append(attrs, @@ -148,7 +162,7 @@ func (s *Span) Event(name string, args ...any) { slog.String(ParentIDName, s.sid.ParentID()), slog.String(TraceIDName, s.tid.String()), slog.String("event", name), - slog.Duration("at", time.Since(s.started)), + slog.Duration("at", at.Sub(s.started)), ) if !SkipSource { @@ -170,11 +184,18 @@ func (s *Span) Event(name string, args ...any) { // // It immediately logs a message with the span name, span information in SpanGroupName and // optional arguments. +// +// Special argument named "finished" of type time.Time can be used to set the finish time of the span. func (s *Span) End(args ...any) { if !s.tracer.logger.Enabled(s.ctx, Level) { return } - dur := time.Since(s.started) + + finished := time.Now() + if p := findArgs[time.Time](args, "finished"); p != nil { + finished = *p + } + dur := finished.Sub(s.started) // keep the order and capacity correct attrs := make([]slog.Attr, 0, 5+1) @@ -200,6 +221,11 @@ func (s *Span) End(args ...any) { logger.LogAttrs(s.ctx, Level, fmt.Sprintf("span %s finished in %v", s.name, dur), attrs...) } +// TraceID returns the trace ID of the span. +func (s *Span) TraceID() TraceID { + return s.tid +} + func callerPtr(skip int) string { _, file, line, ok := runtime.Caller(skip) if !ok { @@ -208,3 +234,26 @@ func callerPtr(skip int) string { return file + ":" + fmt.Sprint(line) } + +func findArgs[T any](args []any, key string) *T { + // find the key in argument key-value pairs + for i := 0; i < len(args)-1; i += 2 { + if k, ok := args[i].(string); ok && k == key { + if result, ok := args[i+1].(T); ok { + return &result + } + } + } + + // find the key in slog.Attrs + for i := range args { + if attr, ok := args[i].(slog.Attr); ok && attr.Key == key { + if result, ok := attr.Value.Any().(T); ok { + return &result + } + } + } + + // not found + return nil +} diff --git a/pkg/strc/trace_test.go b/pkg/strc/trace_test.go index 7aedf52..5e9c955 100644 --- a/pkg/strc/trace_test.go +++ b/pkg/strc/trace_test.go @@ -8,9 +8,11 @@ import ( "regexp" "strings" "testing" + "time" ) func TestLogTextHandler(t *testing.T) { + t.Setenv("TZ", "UTC") var buf bytes.Buffer src = rand.NewSource(0) @@ -56,4 +58,71 @@ func TestLogTextHandler(t *testing.T) { s.End() check(`time=? level=DEBUG msg="span ? finished in ?" span.name=level1 span.id=kYcTpgn span.parent=IvQORsV span.trace=bqzcRlJahlbbBZH span.dur=? span.source=?`) + + tm, _ := time.Parse(time.RFC3339, "2013-05-13T19:30:00Z") + s, _ = Start(ctx, "custom", "started", tm) + check(`time=? level=DEBUG msg="span custom started" span.started=2013-05-13T19:30:00.000Z span.name=custom span.id=VIPEcES span.parent=IvQORsV span.trace=bqzcRlJahlbbBZH span.source=?`) + + s.Event("one", "at", tm.Add(1*time.Minute)) + if !strings.Contains(buf.String(), "span.at=1m0s") { + t.Errorf("buffer does not contain at: %s", buf.String()) + } + check(`time=? level=DEBUG msg="span custom event one" span.started=2013-05-13T19:30:00.000Z span.at=? span.name=custom span.id=VIPEcES span.parent=IvQORsV span.trace=bqzcRlJahlbbBZH span.event=one span.at=? span.source=?`) + + s.End("finished", tm.Add(10*time.Minute)) + if !strings.Contains(buf.String(), "span.dur=10m0s") { + t.Errorf("buffer does not contain duration: %s", buf.String()) + } + check(`time=? level=DEBUG msg="span ? finished in ?" span.started=2013-05-13T19:30:00.000Z span.finished=2013-05-13T19:40:00.000Z span.name=custom span.id=VIPEcES span.parent=IvQORsV span.trace=bqzcRlJahlbbBZH span.dur=? span.source=?`) +} + +func TestFindArgsPairs(t *testing.T) { + one := 1 + two := 2 + tests := []struct { + args []any + key string + want *int + }{ + {[]any{}, "a", nil}, + {[]any{"a"}, "a", nil}, + {[]any{"a", 1}, "a", &one}, + {[]any{"a", "1"}, "a", nil}, + {[]any{"a", 1, "b", 2}, "b", &two}, + {[]any{"a", 1, "b", 2}, "c", nil}, + {[]any{"a", 1, "b"}, "b", nil}, + {[]any{"a", 1, "b", 2, "a", 3}, "a", &one}, + } + + for _, tt := range tests { + t.Run("", func(t *testing.T) { + got := findArgs[int](tt.args, tt.key) + if (got == nil) != (tt.want == nil) || (got != nil && *got != *tt.want) { + t.Errorf("got %v, want %v", got, tt.want) + } + }) + } +} + +func TestFindArgsAttrs(t *testing.T) { + tm, _ := time.Parse("2006-01-02T15:04:05Z, MST", "2013-05-13T19:30:00Z, CET") + tests := []struct { + args []any + key string + want *time.Time + }{ + {[]any{}, "a", nil}, + {[]any{slog.String("x", "v")}, "a", nil}, + {[]any{slog.String("a", "v")}, "a", nil}, + {[]any{slog.Time("a", tm)}, "a", &tm}, + } + + for _, tt := range tests { + t.Run("", func(t *testing.T) { + got := findArgs[time.Time](tt.args, tt.key) + if (got == nil) != (tt.want == nil) || (got != nil && *got != *tt.want) { + t.Errorf("got %v, want %v", got, tt.want) + } + }) + } }