klogga v0.3 (#10)

klogga v0.3

AUTHORS.md

@@ -2,3 +2,4 @@ The following authors have created the source code of "klogga" <br>
 published and distributed by AO Kaspersky Lab as the owner: <br>
 
 Danila Protsenko <[email protected]> <[email protected]> <br>
+Artem Doktor <[email protected]> <[email protected]> <br>

LICENSE.TXT

@@ -1,6 +1,8 @@
 MIT License
 
-Copyright (c) 2021 klogga contributors
+Copyright (c) 2022 AO Kaspersky Lab
+Copyright (c) 2022 klogga contributors
+All Rights Reserved
 
 Permission is hereby granted, free of charge, to any person obtaining a copy
 of this software and associated documentation files (the "Software"), to deal

README.md

@@ -1,8 +1,91 @@
 # Introduction 
 Opinionated logging-audit-tracing library.
-Data collected via klogga can be configured to be exported to different sources, including traditional text logs, but with emphasis on structured storages, primarily time-series databases and Open Telemetry.
+Data collected via **klogga** can be configured to be exported to different sources, including traditional text logs, but with emphasis on structured storages, primarily time-series databases and Open Telemetry.
+
+The ideology is explained here (in russian) [Logging as fact-stream](https://www.youtube.com/watch?v=1lcKzy6j6-k)
+
+**klogga** is in development and as of yet does not even have a 1.0 release.
+API is subject to changes, although we do not expect any.
+It is used extensively in Kaspersky internal projects written in go.
 
 # Getting Started
-import klogga
-configure your root tracer, don't forget to use batcher for buffered traces
-see examples/tracers_tree.go
+## Basic
+Import klogga, configure your root tracer, don't forget to use batcher for buffered traces
+see [examples](examples/basic_app/main.go)
+
+```go
+package main
+
+import (
+	"context"
+	"github.com/KasperskyLab/klogga"
+	"github.com/KasperskyLab/klogga/util"
+	"time"
+)
+
+func main() {
+	// kreating a factory, with the simplest exporter
+	tf := util.DefaultFactory()
+
+	// kreating a tracer with a package name
+	trs := tf.NamedPkg()
+
+	// starting a span
+	// for now, we'll ignore context
+	span, _ := klogga.Start(context.Background())
+	// span will be written on func exit
+	defer trs.Finish(span)
+
+	// tag - potentially indexed
+	span.Tag("app", "hello-world")
+	// value - for metrics, or bigger values
+	span.Val("meaning", 42)
+	// sleep a bit, to have us some non-zero duration
+	time.Sleep(154 * time.Millisecond)
+}
+```
+OUTPUT:
+```
+2022-02-03 04:05:06.789 I main [main.] main() (155.17ms); app:'hello-world'; meaning:'42'; id: 65C6p2Mq2N4; trace: 4nxwjs5WR9G9A-1-dw4cqA
+```
+
+## Extended
+
+**klogga** comes with [fx](https://github.com/uber-go/fx) integration. <br>
+See [fx example](examples/fx_app/main.go)
+
+
+# Features and ideas
+This list will be covered and structured in the future.
+
+- logging basic information automatically without manual setup
+- logging code information for easy search (uses reflection)
+- tracing support: parent-child spans and trace-id
+- opentelemetry support
+- TODO go fuzz tests
+- TODO trace information propagation support for HTTP, GRPC 
+- TODO transport support
+- TODO postgres type mapping customization
+- TODO span serialization to protobuf
+- TODO elasticsearch exporter (if opentelemetry is not enough)
+- TODO more docs for postgreSQL & timescaleDB integration
+- TODO increase test coverage (~60% to ~80%)
+
+
+# Running tests
+## Unit test
+Unit tests do not require any environment, all tests that require environment will be skipped
+```shell
+go test ./...
+```
+
+
+## Integration tests
+Postgresql (timescaleDB) tests can be run on any empty database.
+Tests use environment variable KLOGGA_PG_CONNECTION_STRING to connect to PG.
+Use [docker-compose.yml](docker-compose.yml) to start default instance.
+Default setup:
+```shell
+podman-compose up -d
+KLOGGA_PG_CONNECTION_STRING='user=postgres password=postgres sslmode=disable' go test ./...
+```

adapters/fx/fx_adapter.go

@@ -22,18 +22,18 @@ func (t fxTracer) LogEvent(event fxevent.Event) {
 	span.Tag("event", reflect.TypeOf(event).String())
 	switch e := event.(type) {
 	case *fxevent.OnStartExecuting:
-		span.OverrideName(e.CallerName).Tag("callee", e.FunctionName)
+		span.OverrideName("OnStartExecuting").Tag("caller", e.CallerName).Tag("callee", e.FunctionName)
 	case *fxevent.OnStartExecuted:
-		span.OverrideName(e.CallerName).Tag("callee", e.FunctionName)
+		span.OverrideName("OnStartExecuted").Tag("caller", e.CallerName).Tag("callee", e.FunctionName)
 		if e.Err != nil {
 			span.ErrVoid(e.Err)
 		} else {
 			span.Message("runtime:" + e.Runtime.String())
 		}
 	case *fxevent.OnStopExecuting:
-		span.OverrideName(e.CallerName).Tag("callee", e.FunctionName)
+		span.OverrideName("OnStopExecuting").Tag("caller", e.CallerName).Tag("callee", e.FunctionName)
 	case *fxevent.OnStopExecuted:
-		span.OverrideName(e.CallerName).Tag("callee", e.FunctionName)
+		span.OverrideName("OnStopExecuted").Tag("caller", e.CallerName).Tag("callee", e.FunctionName)
 		if e.Err != nil {
 			span.ErrVoid(e.Err)
 		} else {
@@ -45,9 +45,9 @@ func (t fxTracer) LogEvent(event fxevent.Event) {
 		span.OverrideName("Provided").
 			Message("output types:" + strings.Join(e.OutputTypeNames, ",")).ErrVoid(e.Err)
 	case *fxevent.Invoking:
-		span.OverrideName(e.FunctionName)
+		span.OverrideName("Invoking").Tag("func", e.FunctionName)
 	case *fxevent.Invoked:
-		span.OverrideName(e.FunctionName)
+		span.OverrideName("Invoked").Tag("func", e.FunctionName)
 		if e.Err != nil {
 			span.ErrSpan(e.Err).Message("stack:" + e.Trace)
 		}
@@ -62,7 +62,7 @@ func (t fxTracer) LogEvent(event fxevent.Event) {
 	case *fxevent.Started:
 		span.OverrideName("Started").ErrVoid(e.Err)
 	case *fxevent.LoggerInitialized:
-		span.OverrideName(e.ConstructorName).ErrVoid(e.Err)
+		span.OverrideName("LoggerInitialized").Tag("caller", e.ConstructorName).ErrVoid(e.Err)
 	}
 }
 
@@ -80,12 +80,15 @@ func Module(tf klogga.TracerProvider) fx.Option {
 
 // Full Set up the default logging for the app
 // registering logging and the klogga factory,
-// that later can be reconfigured with more loggers
+// that later can be reconfigured with more loggers via fx.Decorate
 func Full() fx.Option {
 	tf := klogga.NewFactory(golog.New(nil))
 	return fx.Options(
 		Module(tf),
 		fx.Supply(tf),
 		fx.Provide(func(tf *klogga.Factory) klogga.TracerProvider { return tf }),
-	)
+		fx.Invoke(func(tf *klogga.Factory, lc fx.Lifecycle) error {
+			lc.Append(fx.Hook{OnStop: tf.Shutdown})
+			return nil
+		}))
 }

adapters/fx/runner.go

@@ -2,6 +2,7 @@ package fx
 
 import (
 	"context"
+	"errors"
 	"fmt"
 	"github.com/KasperskyLab/klogga"
 	"go.uber.org/fx"
@@ -56,20 +57,22 @@ func (rr RunnersGroup) RegisterWithErrors(tf klogga.TracerProvider, lc fx.Lifecy
 		ctx, cancelFunc := context.WithCancel(context.Background())
 		lc.Append(ToHookWithCtx(runner, cancelFunc))
 		go func(r Runner) {
+			runnerName := reflect.TypeOf(r).String()
 			select {
 			case err := <-re.Error():
+				if err == nil {
+					err = errors.New("<nil error>")
+				}
 				klogga.Message("runner error").
-					Tag("runner", reflect.TypeOf(r).String()).
-					ErrSpan(err).FlushTo(trs)
-			case <-ctx.Done():
-
-			}
-
-			if err := s.Shutdown(); err != nil {
-				klogga.Message("shutdowner error").
-					Tag("runner", reflect.TypeOf(r).String()).
+					Tag("runner", runnerName).
 					ErrSpan(err).FlushTo(trs)
 
+				if err := s.Shutdown(); err != nil {
+					klogga.Message("shutdowner error").
+						Tag("runner", runnerName).
+						ErrSpan(err).FlushTo(trs)
+				}
+			case <-ctx.Done():
 			}
 		}(runner)
 	}
@@ -86,9 +89,8 @@ func ToHookWithCtx(r Runner, onStopped context.CancelFunc) fx.Hook {
 	return fx.Hook{
 		OnStart: r.Start,
 		OnStop: func(ctx context.Context) error {
-			err := r.Stop(ctx)
-			onStopped()
-			return err
+			defer onStopped()
+			return r.Stop(ctx)
 		},
 	}
 }

adapters/grpc/grpc_adapter.go

@@ -12,8 +12,6 @@ type LoggerV2 struct {
 }
 
 type Conf struct {
-	// 0 - log everything
-	// 4 - log nothing
 	VerbosityLevel klogga.LogLevel
 }
 

batcher/batcher.go

@@ -44,10 +44,16 @@ func (c *Config) GetBufferSize() int {
 	return c.GetBatchSize() * 5
 }
 
-func ConfigDefault() Config {
+// ConfigDefault generates default batcher config
+// non-nil optional config will be used instead
+func ConfigDefault(cc ...*Config) Config {
+	if len(cc) > 0 && cc[0] != nil {
+		return *cc[0]
+	}
 	return Config{
-		BatchSize: 20,
-		Timeout:   2 * time.Second,
+		BatchSize:  512,
+		BufferSize: 2048,
+		Timeout:    5 * time.Second,
 	}
 }
 
@@ -132,8 +138,12 @@ func (b *Batcher) Write(ctx context.Context, spans []*klogga.Span) error {
 
 func (b *Batcher) Shutdown(ctx context.Context) (err error) {
 	b.TriggerFlush()
+	if b.stop == nil {
+		return nil
+	}
 	select {
 	case b.stop <- struct{}{}:
+		b.stop = nil
 	case <-ctx.Done():
 		err = ctx.Err()
 	}

batcher/batcher_test.go

@@ -4,6 +4,7 @@ import (
 	"github.com/KasperskyLab/klogga"
 	"github.com/KasperskyLab/klogga/util/testutil"
 	"github.com/stretchr/testify/require"
+	"sync"
 	"testing"
 	"time"
 )
@@ -146,3 +147,41 @@ func TestWriteLotsOfSpans(t *testing.T) {
 	time.Sleep(150 * time.Millisecond)
 	require.True(t, len(tw.GetSpans()) >= 10)
 }
+
+func TestShutdownTwice(t *testing.T) {
+	tw := &exporterStub{}
+	rawTracer := New(
+		tw, Config{
+			BatchSize: 1000,
+			Timeout:   100 * time.Millisecond,
+		},
+	)
+	tf := klogga.NewFactory(rawTracer)
+
+	err := tf.Shutdown(testutil.Timeout())
+	require.NoError(t, err)
+	err = tf.Shutdown(testutil.Timeout())
+	require.NoError(t, err)
+}
+
+func TestShutdownManyGoroutines(t *testing.T) {
+	tw := &exporterStub{}
+	rawTracer := New(
+		tw, Config{
+			BatchSize: 1000,
+			Timeout:   100 * time.Millisecond,
+		},
+	)
+	tf := klogga.NewFactory(rawTracer)
+
+	wg := sync.WaitGroup{}
+	for i := 0; i < 10; i++ {
+		go func() {
+			wg.Add(1)
+			defer wg.Done()
+			err := tf.Shutdown(testutil.Timeout())
+			require.NoError(t, err)
+		}()
+	}
+	wg.Wait()
+}

examples/basic_app/main.go

@@ -3,13 +3,13 @@ package main
 import (
 	"context"
 	"github.com/KasperskyLab/klogga"
-	"github.com/KasperskyLab/klogga/exporters/golog"
+	"github.com/KasperskyLab/klogga/util"
 	"time"
 )
 
 func main() {
 	// kreating a factory, with the simplest exporter
-	tf := klogga.NewFactory(golog.New(nil))
+	tf := util.DefaultFactory()
 
 	// kreating a tracer with a package name
 	trs := tf.NamedPkg()
@@ -26,5 +26,4 @@ func main() {
 	span.Val("meaning", 42)
 	// sleep a bit, to have us some non-zero duration
 	time.Sleep(154 * time.Millisecond)
-
 }

examples/fx_app/main.go

@@ -0,0 +1,60 @@
+package main
+
+import (
+	"context"
+	"github.com/KasperskyLab/klogga"
+	fxAdapter "github.com/KasperskyLab/klogga/adapters/fx"
+	"go.uber.org/fx"
+	"time"
+)
+
+func main() {
+	fx.New(CreateApp()).Run()
+}
+
+func CreateApp() fx.Option {
+	return fx.Options(
+		fx.Provide(NewRunner,
+			fx.Annotate(func(r *Runner) fxAdapter.Runner { return r }, fxAdapter.TagRunner...)),
+		fxAdapter.Full(),
+		fx.Invoke(fxAdapter.RegisterRunners), // register runnerA
+	)
+}
+
+type Runner struct {
+	trs  klogga.Tracer
+	stop chan struct{}
+}
+
+func NewRunner(trsFactory klogga.TracerProvider) *Runner {
+	return &Runner{
+		trs: trsFactory.Named("runner_a"),
+	}
+}
+
+func (r *Runner) Start(ctx context.Context) error {
+	span := klogga.StartLeaf(ctx)
+	defer r.trs.Finish(span)
+
+	go func() {
+		for i := 0; ; i++ {
+			r.LogSomething(i)
+			select {
+			case <-r.stop:
+				return
+			case <-time.After(2 * time.Second):
+			}
+		}
+	}()
+	return nil
+}
+
+func (*Runner) Stop(context.Context) error {
+	return nil
+}
+
+func (r *Runner) LogSomething(iteration int) {
+	span := klogga.StartLeaf(context.Background(), klogga.WithName("run_func"))
+	defer r.trs.Finish(span)
+	span.Val("iteration", iteration)
+}