diff --git a/backend/v3/domain/invoker_logging.go b/backend/v3/domain/invoker_logging.go index 6b987d4bc..525509690 100644 --- a/backend/v3/domain/invoker_logging.go +++ b/backend/v3/domain/invoker_logging.go @@ -4,7 +4,7 @@ import ( "context" "time" - slogctx "github.com/veqryn/slog-context" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" ) // loggingInvoker decorates each command with logging. @@ -21,7 +21,7 @@ func NewLoggingInvoker(next Invoker) *loggingInvoker { func (i *loggingInvoker) Invoke(ctx context.Context, executor Executor, opts *InvokeOpts) (err error) { start := time.Now() - logger := slogctx.FromCtx(ctx) + logger := logging.FromCtx(ctx) logger.InfoContext(ctx, "invoking", "name", executor.String()) err = i.execute(ctx, executor, opts) diff --git a/backend/v3/instrumentation/instrumentation.go b/backend/v3/instrumentation/instrumentation.go index d7bc7df05..cecad1918 100644 --- a/backend/v3/instrumentation/instrumentation.go +++ b/backend/v3/instrumentation/instrumentation.go @@ -4,7 +4,6 @@ package instrumentation import ( "context" - "log/slog" "net/http" "slices" "strings" @@ -69,11 +68,6 @@ func NewMeter(name string, options ...metric.MeterOption) *Meter { } } -// Logger returns the globally configured logger. -func Logger() *slog.Logger { - return slog.Default() -} - func RequestFilter(ignoredPrefix ...string) otelhttp.Filter { return func(r *http.Request) bool { return !slices.ContainsFunc( diff --git a/backend/v3/instrumentation/logformat_enumer.go b/backend/v3/instrumentation/logformat_enumer.go index 5ee05de16..84158c889 100644 --- a/backend/v3/instrumentation/logformat_enumer.go +++ b/backend/v3/instrumentation/logformat_enumer.go @@ -24,7 +24,7 @@ func (i LogFormat) String() string { // Re-run the stringer command to generate them again. func _LogFormatNoOp() { var x [1]struct{} - _ = x[LogFormatUndefined-(0)] + _ = x[LogFormatUnspecified-(0)] _ = x[LogFormatDisabled-(1)] _ = x[LogFormatText-(2)] _ = x[LogFormatJSON-(3)] @@ -32,11 +32,11 @@ func _LogFormatNoOp() { _ = x[LogFormatGCPErrorReporting-(5)] } -var _LogFormatValues = []LogFormat{LogFormatUndefined, LogFormatDisabled, LogFormatText, LogFormatJSON, LogFormatGCP, LogFormatGCPErrorReporting} +var _LogFormatValues = []LogFormat{LogFormatUnspecified, LogFormatDisabled, LogFormatText, LogFormatJSON, LogFormatGCP, LogFormatGCPErrorReporting} var _LogFormatNameToValueMap = map[string]LogFormat{ - _LogFormatName[0:0]: LogFormatUndefined, - _LogFormatLowerName[0:0]: LogFormatUndefined, + _LogFormatName[0:0]: LogFormatUnspecified, + _LogFormatLowerName[0:0]: LogFormatUnspecified, _LogFormatName[0:8]: LogFormatDisabled, _LogFormatLowerName[0:8]: LogFormatDisabled, _LogFormatName[8:12]: LogFormatText, diff --git a/backend/v3/instrumentation/logging/connect_handler.go b/backend/v3/instrumentation/logging/connect_handler.go deleted file mode 100644 index 0d3e3e475..000000000 --- a/backend/v3/instrumentation/logging/connect_handler.go +++ /dev/null @@ -1,34 +0,0 @@ -package logging - -import ( - "context" - "slices" - "strings" - - "connectrpc.com/connect" - slogctx "github.com/veqryn/slog-context" - - "github.com/zitadel/zitadel/backend/v3/instrumentation" -) - -func NewConnectInterceptor(next connect.UnaryFunc, ignoredMethodSuffixes ...string) connect.UnaryFunc { - return func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) { - if slices.ContainsFunc(ignoredMethodSuffixes, func(s string) bool { - return strings.HasSuffix(req.Spec().Procedure, s) - }) { - return next(ctx, req) - } - - logger := instrumentation.Logger() - ctx = instrumentation.SetConnectRequestDetails(ctx, req) - ctx = slogctx.NewCtx(ctx, logger) - - resp, err := next(ctx, req) - var code connect.Code - if err != nil { - code = connect.CodeOf(err) - } - logger.InfoContext(ctx, "connect RPC request", "code", code) - return resp, err - } -} diff --git a/backend/v3/instrumentation/logging/grpc_handler.go b/backend/v3/instrumentation/logging/grpc_handler.go deleted file mode 100644 index 64e88e6ba..000000000 --- a/backend/v3/instrumentation/logging/grpc_handler.go +++ /dev/null @@ -1,36 +0,0 @@ -package logging - -import ( - "context" - "slices" - "strings" - - slogctx "github.com/veqryn/slog-context" - "google.golang.org/grpc" - "google.golang.org/grpc/codes" - "google.golang.org/grpc/status" - - "github.com/zitadel/zitadel/backend/v3/instrumentation" -) - -func NewGrpcInterceptor(ignoredMethodSuffixes ...string) grpc.UnaryServerInterceptor { - return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, next grpc.UnaryHandler) (any, error) { - if slices.ContainsFunc(ignoredMethodSuffixes, func(s string) bool { - return strings.HasSuffix(info.FullMethod, s) - }) { - return next(ctx, req) - } - - logger := instrumentation.Logger() - ctx = instrumentation.SetGrpcRequestDetails(ctx, info) - ctx = slogctx.NewCtx(ctx, logger) - - resp, err := next(ctx, req) - var code codes.Code - if err != nil { - code = status.Code(err) - } - logger.InfoContext(ctx, "gRPC request", "code", code) - return resp, err - } -} diff --git a/backend/v3/instrumentation/logging/http_handler.go b/backend/v3/instrumentation/logging/http_handler.go deleted file mode 100644 index 898003abf..000000000 --- a/backend/v3/instrumentation/logging/http_handler.go +++ /dev/null @@ -1,45 +0,0 @@ -package logging - -import ( - "net/http" - - slogctx "github.com/veqryn/slog-context" - - "github.com/zitadel/zitadel/backend/v3/instrumentation" -) - -func NewHandler(next http.Handler, service string, ignoredPrefix ...string) http.Handler { - filter := instrumentation.RequestFilter(ignoredPrefix...) - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - if !filter(r) { - next.ServeHTTP(w, r) - return - } - logger := instrumentation.Logger() - ctx := instrumentation.SetHttpRequestDetails(r.Context(), service, r) - ctx = slogctx.NewCtx(ctx, logger) - sw := &statusWriter{ResponseWriter: w} - - next.ServeHTTP(sw, r.WithContext(ctx)) - - logger.InfoContext(ctx, "http request", "status", sw.status) - }) -} - -// statusWriter is a [http.ResponseWriter] that captures the status code for logging. -type statusWriter struct { - http.ResponseWriter - status int -} - -func (w *statusWriter) Write(p []byte) (int, error) { - if w.status == 0 { - w.status = http.StatusOK - } - return w.ResponseWriter.Write(p) -} - -func (w *statusWriter) WriteHeader(statusCode int) { - w.status = statusCode - w.ResponseWriter.WriteHeader(statusCode) -} diff --git a/backend/v3/instrumentation/logging/logging.go b/backend/v3/instrumentation/logging/logging.go new file mode 100644 index 000000000..16c43b752 --- /dev/null +++ b/backend/v3/instrumentation/logging/logging.go @@ -0,0 +1,221 @@ +// Package logging provides utilities for structured logging with context support. +// It builds on top of slog and slog-context to offer a consistent logging experience +// across different parts of the application by categorizing logs into different streams. +// +// The package uses the global [slog.Default] logger as the base logger, +// which is configured at application startup to set the desired logging level and output format. +// It provides functions to create new loggers for specific streams and to +// add logging capabilities to contexts. +// Streams are defined using the [Stream] enumeration. +// Log context can be created using [NewCtx], and loggers can be retrieved from contexts using [FromCtx]. +// Streams are typically initialized at the start of different application components +// (e.g., request handling, event processing) to ensure that all logs generated within those components +// are tagged appropriately. +// +// Example usage: +// +// // Initialize a context for request handling, typically done in middleware +// ctx := logging.NewCtx(context.Background(), logging.StreamRequest, slog.String("request_id", "12345")) +// // Somewhere deeper in the call stack +// logging.Info(ctx, "Something to log") +// +// This will produce a log entry with the stream set to "request" and include the request ID. +package logging + +import ( + "context" + "errors" + "log/slog" + "os" + "runtime" + "time" + + slogctx "github.com/veqryn/slog-context" + "github.com/zitadel/sloggcp" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/cmd/build" + "github.com/zitadel/zitadel/internal/zerrors" +) + +// Stream represents a logging stream for categorizing log entries. +// This is a type alias for [instrumentation.Stream] to expose it in this package. +type Stream = instrumentation.Stream + +const ( + StreamRuntime = instrumentation.StreamRuntime // Application runtime logs. + StreamReady = instrumentation.StreamReady // Readiness and liveness checks. + StreamRequest = instrumentation.StreamRequest // API request handling. + StreamEventPusher = instrumentation.StreamEventPusher // Event pushing to the database. + StreamEventHandler = instrumentation.StreamEventHandler // Event handling and processing. + StreamQueue = instrumentation.StreamQueue // Queue operations and job processing. +) + +var noop = slog.New(slog.DiscardHandler) + +// New creates a new logger with the given stream and additional arguments. +func New(stream Stream, args ...any) *slog.Logger { + if !instrumentation.IsStreamEnabled(stream) { + return noop + } + args = append(args, + slog.String("stream", stream.String()), + slog.String("version", build.Version()), + ) + return slog.Default().With(args...) +} + +// NewCtx creates a new context with a logger for the given stream and additional arguments. +// Use the [FromCtx] or other helpers to retrieve the logger from the context. +// An existing logger in the context will be replaced. +func NewCtx(ctx context.Context, stream Stream, args ...any) context.Context { + logger := New(stream, args...) + return ToCtx(ctx, logger) +} + +// ToCtx adds the given logger to the context. +// See [slogctx.NewCtx]. +func ToCtx(ctx context.Context, logger *slog.Logger) context.Context { + return slogctx.NewCtx(ctx, logger) +} + +// FromCtx retrieves the logger from the context. +// See [slogctx.FromCtx]. +func FromCtx(ctx context.Context) *slog.Logger { + return slogctx.FromCtx(ctx) +} + +// With adds the given arguments to the logger in the context. +// See [slogctx.With]. +func With(ctx context.Context, args ...any) context.Context { + return slogctx.With(ctx, args...) +} + +// WithGroup adds a group to the logger in the context. +// See [slogctx.WithGroup]. +func WithGroup(ctx context.Context, name string) context.Context { + return slogctx.WithGroup(ctx, name) +} + +// Log logs a message with the given level and arguments using the logger from the context. +// See [slogctx.Log]. +func Log(ctx context.Context, level slog.Level, msg string, args ...any) { + log(ctx, FromCtx(ctx), level, msg, 1, args...) +} + +// Debug logs a debug message using the logger from the context. +// See [slogctx.Debug]. +func Debug(ctx context.Context, msg string, args ...any) { + log(ctx, FromCtx(ctx), slog.LevelDebug, msg, 1, args...) +} + +// Info logs an info message using the logger from the context. +// See [slogctx.Info]. +func Info(ctx context.Context, msg string, args ...any) { + log(ctx, FromCtx(ctx), slog.LevelInfo, msg, 1, args...) +} + +// Warn logs a warning message using the logger from the context. +// See [slogctx.Warn]. +func Warn(ctx context.Context, msg string, args ...any) { + log(ctx, FromCtx(ctx), slog.LevelWarn, msg, 1, args...) +} + +// Error logs an error message using the logger from the context. +// See [slogctx.Error]. +func Error(ctx context.Context, msg string, args ...any) { + log(ctx, FromCtx(ctx), slog.LevelError, msg, 1, args...) +} + +// WithError adds an error attribute to the logger from the context and returns the new logger. +// If the error is not a [zerrors.ZitadelError], it is wrapped in a generic ZitadelError with kind [zerrors.KindUnknown]. +func WithError(ctx context.Context, err error) *ErrorContextLogger { + var target *zerrors.ZitadelError + if !errors.As(err, &target) { + target = zerrors.CreateZitadelError(zerrors.KindUnknown, err, "LOG-Ao5ch", "an unknown error occurred", 1) + } + return &ErrorContextLogger{ + ctx: ctx, + logger: slogctx.FromCtx(ctx).With(slogctx.Err(target)), + canTerminate: true, + } +} + +// OnError returns a logger that includes the error as an attribute when err is non-nil. +// If err is nil, it returns a no-op logger. +// If err is not a [zerrors.ZitadelError], it is wrapped as a generic ZitadelError of kind [zerrors.KindUnknown]. +func OnError(ctx context.Context, err error) *ErrorContextLogger { + if err == nil { + return &ErrorContextLogger{ctx, noop, false} + } + var target *zerrors.ZitadelError + if !errors.As(err, &target) { + target = zerrors.CreateZitadelError(zerrors.KindUnknown, err, "LOG-ii6Pi", "an unknown error occurred", 1) + } + return &ErrorContextLogger{ + ctx: ctx, + logger: slogctx.FromCtx(ctx).With(slogctx.Err(target)), + canTerminate: true, + } +} + +type ErrorContextLogger struct { + ctx context.Context + logger *slog.Logger + // canTerminate sets whether Panic/Fatal should actually call panic or os.Exit. + // False when OnError returned a no-op logger, true in all other cases. + canTerminate bool +} + +func (l *ErrorContextLogger) Debug(msg string, args ...any) { + log(l.ctx, l.logger, slog.LevelDebug, msg, 1, args...) +} + +func (l *ErrorContextLogger) Info(msg string, args ...any) { + log(l.ctx, l.logger, slog.LevelInfo, msg, 1, args...) +} + +func (l *ErrorContextLogger) Warn(msg string, args ...any) { + log(l.ctx, l.logger, slog.LevelWarn, msg, 1, args...) +} + +func (l *ErrorContextLogger) Error(msg string, args ...any) { + log(l.ctx, l.logger, slog.LevelError, msg, 1, args...) +} + +// Panic logs a [sloggcp.LevelAlert] leveled message and panics. +// If the logger was created via [OnError] with a nil error, this method does nothing. +func (l *ErrorContextLogger) Panic(msg string, args ...any) { + log(l.ctx, l.logger, sloggcp.LevelAlert, msg, 1, args...) + if l.canTerminate { + panic(msg) + } +} + +// Fatal logs a [sloggcp.LevelEmergency] leveled message and exits the application with code 1. +// If the logger was created via [OnError] with a nil error, this method does nothing. +func (l *ErrorContextLogger) Fatal(msg string, args ...any) { + log(l.ctx, l.logger, sloggcp.LevelEmergency, msg, 1, args...) + if l.canTerminate { + exit(1) + } +} + +// exit is a variable to allow testing of Fatal without exiting the test process. +var exit = os.Exit + +// log is a helper function that logs a message with the given level and arguments using the provided logger. +func log(ctx context.Context, logger *slog.Logger, level slog.Level, msg string, skip int, args ...any) { + handler := logger.Handler() + if !handler.Enabled(ctx, level) { + return + } + var pcs [1]uintptr + if instrumentation.IsAddSourceEnabled() { + runtime.Callers(skip+2, pcs[:]) + + } + r := slog.NewRecord(time.Now(), level, msg, pcs[0]) + r.Add(args...) + _ = logger.Handler().Handle(ctx, r) +} diff --git a/backend/v3/instrumentation/logging/logging_test.go b/backend/v3/instrumentation/logging/logging_test.go new file mode 100644 index 000000000..7b71c0b53 --- /dev/null +++ b/backend/v3/instrumentation/logging/logging_test.go @@ -0,0 +1,583 @@ +package logging + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "log/slog" + "os" + "sync" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/internal/zerrors" +) + +var globalLock sync.Mutex + +type testLogEntry struct { + Level string + Msg string + Err *testLogError `json:",omitempty"` + Foo string + Group struct { + V int + } +} + +type testLogError struct { + Kind string + Parent string + Message string + ID string +} + +func init() { + // Only enable StreamRuntime for tests + instrumentation.EnableStreams(StreamRuntime) +} + +// prepareDefaultLogger sets the global default logger to a JSON logger writing to a buffer. +// It returns a function that MUST be called to retrieve exactly one logged entry and release the global lock. +func prepareDefaultLogger() (done func() (*testLogEntry, error)) { + globalLock.Lock() + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{ + Level: slog.LevelDebug, + AddSource: false, + })) + slog.SetDefault(logger) + + return func() (*testLogEntry, error) { + defer globalLock.Unlock() + if buf.Len() == 0 { + return nil, nil + } + + entry := new(testLogEntry) + decoder := json.NewDecoder(&buf) + if err := decoder.Decode(entry); err != nil { + return nil, err + } + return entry, nil + } +} + +func TestNew(t *testing.T) { + tests := []struct { + name string + stream Stream + want *testLogEntry + }{ + { + name: "enabled stream", + stream: StreamRuntime, + want: &testLogEntry{ + Level: "INFO", + Msg: "test message", + Foo: "bar", + }, + }, + { + name: "disabled stream", + stream: StreamEventPusher, + want: nil, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + done := prepareDefaultLogger() + logger := New(tt.stream, slog.String("foo", "bar")) + logger.Info("test message") + got, err := done() + require.NoError(t, err) + assert.Equal(t, tt.want, got) + }) + } +} + +func TestFromCtx(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + slog.String("foo", "bar"), + ) + FromCtx(ctx).Info("test message") + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestWith(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + ctx = With(ctx, slog.String("foo", "bar")) + FromCtx(ctx).Info("test message") + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestWithGroup(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + ctx = WithGroup(ctx, "group") + ctx = With(ctx, slog.Int("v", 42)) + FromCtx(ctx).Info("test message") + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Group: struct{ V int }{V: 42}, + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestLog(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + Log(ctx, slog.LevelInfo, "test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestDebug(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + Debug(ctx, "test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "DEBUG", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestInfo(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + Info(ctx, "test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestWarn(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + Warn(ctx, "test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "WARN", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestError(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + Error(ctx, "test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "ERROR", + Msg: "test message", + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestWithError(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + err := errors.New("some error") + logger := WithError(ctx, err) + logger.Info("test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "some error", + Message: "an unknown error occurred", + ID: "LOG-Ao5ch", + }, + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestOnError(t *testing.T) { + tests := []struct { + name string + err error + want *testLogEntry + }{ + { + name: "nil error", + err: nil, + }, + { + name: "non-zitadel error", + err: errors.New("some error"), + want: &testLogEntry{ + Level: "INFO", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "some error", + Message: "an unknown error occurred", + ID: "LOG-ii6Pi", + }, + Foo: "bar", + }, + }, + { + name: "zitadel error", + err: zerrors.CreateZitadelError( + zerrors.KindNotFound, + errors.New("parent error"), + "ZIT-404", + "resource not found", + 0, + ), + want: &testLogEntry{ + Level: "INFO", + Msg: "test message", + Err: &testLogError{ + Kind: "NotFound", + Parent: "parent error", + Message: "resource not found", + ID: "ZIT-404", + }, + Foo: "bar", + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + logger := OnError(ctx, tt.err) + logger.Info("test message", slog.String("foo", "bar")) + got, err := done() + require.NoError(t, err) + assert.Equal(t, tt.want, got) + }) + } +} + +func TestErrorContextLogger_Debug(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + WithError(ctx, nil).Debug("test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "DEBUG", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "", + Message: "an unknown error occurred", + ID: "LOG-Ao5ch", + }, + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestErrorContextLogger_Info(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + WithError(ctx, nil).Info("test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "INFO", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "", + Message: "an unknown error occurred", + ID: "LOG-Ao5ch", + }, + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestErrorContextLogger_Warn(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + WithError(ctx, nil).Warn("test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "WARN", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "", + Message: "an unknown error occurred", + ID: "LOG-Ao5ch", + }, + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestErrorContextLogger_Error(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + WithError(ctx, nil).Error("test message", slog.String("foo", "bar")) + want := &testLogEntry{ + Level: "ERROR", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "", + Message: "an unknown error occurred", + ID: "LOG-Ao5ch", + }, + Foo: "bar", + } + got, err := done() + require.NoError(t, err) + assert.Equal(t, want, got) +} + +func TestErrorContextLogger_Panic(t *testing.T) { + tests := []struct { + name string + construct func(context.Context, error) *ErrorContextLogger + err error + want *testLogEntry + wantPanic any + }{ + { + name: "with zitadel error", + construct: WithError, + err: zerrors.CreateZitadelError( + zerrors.KindNotFound, + errors.New("parent error"), + "ZIT-404", + "resource not found", + 0, + ), + want: &testLogEntry{ + Level: "ERROR+4", + Msg: "test message", + Err: &testLogError{ + Kind: "NotFound", + Parent: "parent error", + Message: "resource not found", + ID: "ZIT-404", + }, + Foo: "bar", + }, + wantPanic: "test message", + }, + { + name: "on nil error", + construct: OnError, + err: nil, + want: nil, + wantPanic: nil, + }, + { + name: "on non-zitadel error", + construct: OnError, + err: errors.New("some error"), + want: &testLogEntry{ + Level: "ERROR+4", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "some error", + Message: "an unknown error occurred", + ID: "LOG-ii6Pi", + }, + Foo: "bar", + }, + wantPanic: "test message", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + var ( + gotPanic any + gotEntry *testLogEntry + err error + ) + + // need to check in defer because of panic + defer func() { + gotPanic = recover() + gotEntry, err = done() + require.NoError(t, err) + assert.Equal(t, tt.want, gotEntry) + assert.Equal(t, tt.wantPanic, gotPanic) + }() + tt.construct(ctx, tt.err).Panic("test message", slog.String("foo", "bar")) + }) + } +} + +func TestErrorContextLogger_Fatal(t *testing.T) { + tests := []struct { + name string + construct func(context.Context, error) *ErrorContextLogger + err error + want *testLogEntry + wantExit int + }{ + { + name: "with zitadel error", + construct: WithError, + err: zerrors.CreateZitadelError( + zerrors.KindNotFound, + errors.New("parent error"), + "ZIT-404", + "resource not found", + 0, + ), + want: &testLogEntry{ + Level: "ERROR+6", + Msg: "test message", + Err: &testLogError{ + Kind: "NotFound", + Parent: "parent error", + Message: "resource not found", + ID: "ZIT-404", + }, + Foo: "bar", + }, + wantExit: 1, + }, + { + name: "on nil error", + construct: OnError, + err: nil, + want: nil, + wantExit: 0, + }, + { + name: "on non-zitadel error", + construct: OnError, + err: errors.New("some error"), + want: &testLogEntry{ + Level: "ERROR+6", + Msg: "test message", + Err: &testLogError{ + Kind: "Unknown", + Parent: "some error", + Message: "an unknown error occurred", + ID: "LOG-ii6Pi", + }, + Foo: "bar", + }, + wantExit: 1, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + done := prepareDefaultLogger() + ctx := NewCtx( + t.Context(), + StreamRuntime, + ) + var gotExit int + exit = func(code int) { + gotExit = code + } + defer func() { + exit = os.Exit + }() + + tt.construct(ctx, tt.err).Fatal("test message", slog.String("foo", "bar")) + gotEntry, err := done() + require.NoError(t, err) + assert.Equal(t, tt.want, gotEntry) + assert.Equal(t, tt.wantExit, gotExit) + }) + } +} diff --git a/backend/v3/instrumentation/metrics/http_handler.go b/backend/v3/instrumentation/metrics/http_handler.go index f03d3b5ac..fa0cac642 100644 --- a/backend/v3/instrumentation/metrics/http_handler.go +++ b/backend/v3/instrumentation/metrics/http_handler.go @@ -1,14 +1,10 @@ package metrics import ( - "context" "net/http" "strings" - "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" "go.opentelemetry.io/otel/attribute" - - "github.com/zitadel/zitadel/backend/v3/instrumentation" ) const ( @@ -23,12 +19,6 @@ const ( ReturnCode = "return_code" ) -type Handler struct { - handler http.Handler - methods []MetricType - filter otelhttp.Filter -} - type MetricType int32 const ( @@ -37,82 +27,13 @@ const ( MetricTypeRequestCount ) -type StatusRecorder struct { - http.ResponseWriter - RequestURI *string - Status int +type StatusRecorder interface { + Status() int } -func (r *StatusRecorder) WriteHeader(status int) { - r.Status = status - r.ResponseWriter.WriteHeader(status) -} - -type Filter func(*http.Request) bool - -func NewHandler(handler http.Handler, metricMethods []MetricType, ignoredEndpoints ...string) http.Handler { - h := Handler{ - handler: handler, - methods: metricMethods, - filter: instrumentation.RequestFilter(ignoredEndpoints...), - } - return &h -} - -type key int - -const requestURI key = iota - -func SetRequestURIPattern(ctx context.Context, pattern string) { - uri, ok := ctx.Value(requestURI).(*string) - if !ok { - return - } - *uri = pattern -} - -// ServeHTTP serves HTTP requests (http.Handler) -func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { - if len(h.methods) == 0 { - h.handler.ServeHTTP(w, r) - return - } - if !h.filter(r) { - // Simply pass through to the handler if a filter rejects the request - h.handler.ServeHTTP(w, r) - return - } - uri := strings.Split(r.RequestURI, "?")[0] - recorder := &StatusRecorder{ - ResponseWriter: w, - RequestURI: &uri, - Status: 200, - } - r = r.WithContext(context.WithValue(r.Context(), requestURI, &uri)) - h.handler.ServeHTTP(recorder, r) - if h.containsMetricsMethod(MetricTypeRequestCount) { - RegisterRequestCounter(recorder, r) - } - if h.containsMetricsMethod(MetricTypeTotalCount) { - RegisterTotalRequestCounter(r) - } - if h.containsMetricsMethod(MetricTypeStatusCode) { - RegisterRequestCodeCounter(recorder, r) - } -} - -func (h *Handler) containsMetricsMethod(method MetricType) bool { - for _, m := range h.methods { - if m == method { - return true - } - } - return false -} - -func RegisterRequestCounter(recorder *StatusRecorder, r *http.Request) { +func RegisterRequestCounter(recorder StatusRecorder, r *http.Request) { var labels = map[string]attribute.Value{ - URI: attribute.StringValue(*recorder.RequestURI), + URI: attribute.StringValue(baseURI(r)), Method: attribute.StringValue(r.Method), } RegisterCounter(RequestCounter, RequestCountDescription) @@ -124,12 +45,16 @@ func RegisterTotalRequestCounter(r *http.Request) { AddCount(r.Context(), TotalRequestCounter, 1, nil) } -func RegisterRequestCodeCounter(recorder *StatusRecorder, r *http.Request) { +func RegisterRequestCodeCounter(recorder StatusRecorder, r *http.Request) { var labels = map[string]attribute.Value{ - URI: attribute.StringValue(*recorder.RequestURI), + URI: attribute.StringValue(baseURI(r)), Method: attribute.StringValue(r.Method), - ReturnCode: attribute.IntValue(recorder.Status), + ReturnCode: attribute.IntValue(recorder.Status()), } RegisterCounter(ReturnCodeCounter, ReturnCodeCounterDescription) AddCount(r.Context(), ReturnCodeCounter, 1, labels) } + +func baseURI(r *http.Request) string { + return strings.Split(r.RequestURI, "?")[0] +} diff --git a/backend/v3/instrumentation/slog.go b/backend/v3/instrumentation/slog.go index 211298580..ec6bc1d3e 100644 --- a/backend/v3/instrumentation/slog.go +++ b/backend/v3/instrumentation/slog.go @@ -3,22 +3,20 @@ package instrumentation import ( "context" "log/slog" - "net/http" "os" - "strings" + "slices" + "sync/atomic" "time" - "connectrpc.com/connect" "github.com/rs/xid" slogmulti "github.com/samber/slog-multi" slogctx "github.com/veqryn/slog-context" slogotel "github.com/veqryn/slog-context/otel" + old_logging "github.com/zitadel/logging" //nolint:staticcheck "github.com/zitadel/sloggcp" "go.opentelemetry.io/contrib/bridges/otelslog" "go.opentelemetry.io/otel/sdk/log" - "google.golang.org/grpc" - http_util "github.com/zitadel/zitadel/internal/api/http" "github.com/zitadel/zitadel/internal/zerrors" ) @@ -27,7 +25,7 @@ type LogFormat int //go:generate enumer -type=LogFormat -trimprefix=LogFormat -text -linecomment -transform=snake const ( // Empty line comment sets empty string of unspecified value - LogFormatUndefined LogFormat = iota // + LogFormatUnspecified LogFormat = iota // LogFormatDisabled LogFormatText LogFormatJSON @@ -36,19 +34,74 @@ const ( LogFormatGCPErrorReporting ) +func (f LogFormat) isDisabled() bool { + return f == LogFormatUnspecified || f == LogFormatDisabled +} + type LogConfig struct { Level slog.Level + Streams []Stream + Mask MaskConfig Format LogFormat AddSource bool Errors ErrorConfig Exporter ExporterConfig } +func (c *LogConfig) SetLegacyConfig(lc *old_logging.Config) { + if lc == nil || !c.Format.isDisabled() { + return + } + err := c.Level.UnmarshalText([]byte(lc.Level)) + if err != nil { + c.Level = slog.LevelInfo + } + c.Format, err = LogFormatString(lc.Formatter.Format) + if err != nil { + c.Format = LogFormatText + } + c.AddSource = lc.AddSource +} + +func (c LogConfig) replacer() replacer { + var replacers []replacer + if len(c.Mask.Keys) > 0 { + replacers = append(replacers, c.Mask.replacer()) + } + if c.Format == LogFormatGCP { + replacers = append(replacers, sloggcp.ReplaceAttr) + } + if c.Format == LogFormatGCPErrorReporting { + replacers = append(replacers, errReplacer()) + } + return chainReplacers(replacers...) +} + +type MaskConfig struct { + Keys []string + Value string +} + +func (c MaskConfig) replacer() replacer { + return func(_ []string, a slog.Attr) slog.Attr { + if slices.Contains(c.Keys, a.Key) { + a.Value = slog.StringValue(c.Value) + } + return a + } +} + type ErrorConfig struct { ReportLocation bool StackTrace bool } +var addSourceEnabled atomic.Bool + +func IsAddSourceEnabled() bool { + return addSourceEnabled.Load() +} + // setLogger configures the global slog logger. // Logs are sent to [os.Stderr] and/or the [log.LoggerProvider]. // @@ -60,12 +113,15 @@ type ErrorConfig struct { // - Request details, such as method and path. func setLogger(provider *log.LoggerProvider, cfg LogConfig) { options := &slog.HandlerOptions{ - AddSource: cfg.AddSource, - Level: cfg.Level, + AddSource: cfg.AddSource, + Level: cfg.Level, + ReplaceAttr: cfg.replacer(), } + addSourceEnabled.Store(cfg.AddSource) + var stdErrHandler slog.Handler switch cfg.Format { - case LogFormatUndefined: + case LogFormatUnspecified: return // uses default slog logger case LogFormatDisabled: stdErrHandler = slog.DiscardHandler @@ -74,14 +130,13 @@ func setLogger(provider *log.LoggerProvider, cfg LogConfig) { case LogFormatJSON: stdErrHandler = slog.NewJSONHandler(os.Stderr, options) case LogFormatGCP: - options.ReplaceAttr = sloggcp.ReplaceAttr stdErrHandler = slog.NewJSONHandler(os.Stderr, options) case LogFormatGCPErrorReporting: zerrors.GCPErrorReportingEnabled(true) - options.ReplaceAttr = replaceErrAttr stdErrHandler = sloggcp.NewErrorReportingHandler(os.Stderr, options) } + EnableStreams(cfg.Streams...) zerrors.EnableReportLocation(cfg.Errors.ReportLocation) zerrors.EnableStackTrace(cfg.Errors.StackTrace) @@ -89,8 +144,8 @@ func setLogger(provider *log.LoggerProvider, cfg LogConfig) { stdErrHandler, &slogctx.HandlerOptions{ Prependers: []slogctx.AttrExtractor{ - domainExtractor, - requestExtractor, + instanceExtractor, + requestIDExtractor, slogotel.ExtractTraceSpanID, slogctx.ExtractPrepended, }, @@ -113,106 +168,65 @@ const ( ProtocolGrpc = "grpc" ) -// SetHttpRequestDetails adds static details to each context aware log entry. -func SetHttpRequestDetails(ctx context.Context, service string, request *http.Request) context.Context { - now := time.Now() - return context.WithValue(ctx, ctxKey{}, &requestDetails{ - protocol: ProtocolHttp, - service: service, - http_method: request.Method, - path: request.URL.Path, - requestID: xid.NewWithTime(now), - start: now, - }) +// Instance is a minimal interface for logging the instance ID. +type Instance interface { + InstanceID() string } -// SetConnectRequestDetails adds static details to each context aware log entry. -func SetConnectRequestDetails(ctx context.Context, request connect.AnyRequest) context.Context { - now := time.Now() - spec := request.Spec() - return context.WithValue(ctx, ctxKey{}, &requestDetails{ - protocol: ProtocolConnect, - service: serviceFromRPCMethod(spec.Procedure), - http_method: request.HTTPMethod(), - path: spec.Procedure, - requestID: xid.NewWithTime(now), - start: now, - }) +// SetInstance adds the instance to the context for logging. +func SetInstance(ctx context.Context, instance Instance) context.Context { + return context.WithValue(ctx, ctxKeyInstance, instance) } -func SetGrpcRequestDetails(ctx context.Context, info *grpc.UnaryServerInfo) context.Context { - now := time.Now() - return context.WithValue(ctx, ctxKey{}, &requestDetails{ - protocol: ProtocolGrpc, - service: serviceFromRPCMethod(info.FullMethod), - http_method: http.MethodPost, // gRPC always uses POST - path: info.FullMethod, - requestID: xid.NewWithTime(now), - start: now, - }) +// SetRequest generates a new [xid.ID] based on the passed request timestamp +// and adds it to the context. +func SetRequestID(ctx context.Context, ts time.Time) context.Context { + return context.WithValue(ctx, ctxKeyRequestID, xid.NewWithTime(ts)) } -type ctxKey struct{} +type ctxKeyType int -type requestDetails struct { - protocol string - service string - http_method string - path string - requestID xid.ID - start time.Time -} +const ( + ctxKeyRequestID ctxKeyType = iota + ctxKeyInstance +) -func (r *requestDetails) attrs() []slog.Attr { - attrs := make([]slog.Attr, 0, 6) - if r.protocol != "" { - attrs = append(attrs, slog.String("protocol", r.protocol)) - } - if r.service != "" { - attrs = append(attrs, slog.String("service", r.service)) - } - if r.http_method != "" { - attrs = append(attrs, slog.String("http_method", r.http_method)) - } - if r.path != "" { - attrs = append(attrs, slog.String("path", r.path)) - } - if !r.requestID.IsZero() { - attrs = append(attrs, slog.String("request_id", r.requestID.String())) - } - if !r.start.IsZero() { - attrs = append(attrs, slog.Duration("duration", time.Since(r.start))) - } - return attrs -} - -func serviceFromRPCMethod(fullMethod string) string { - parts := strings.Split(fullMethod, "/") - if len(parts) >= 2 { - return parts[1] - } - return "unknown" -} - -// domainExtractor sets the sanitized request hosts from [http_util.DomainCtx] to a log entry. -func domainExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { - return []slog.Attr{ - slog.Any("domain", http_util.DomainContext(ctx)), - } -} - -// requestExtractor sets the request details from [requestDetails] to a log entry. -func requestExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { - if r, ok := ctx.Value(ctxKey{}).(*requestDetails); ok { - return r.attrs() +// instanceExtractor sets the instance ID from [Instance] to a log entry. +func instanceExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { + if instance, ok := ctx.Value(ctxKeyInstance).(Instance); ok { + return []slog.Attr{ + slog.String("instance", instance.InstanceID()), + } } return nil } -// replaceErrAttr renames the "err" attribute to the Google Cloud Platform compatible error key. -func replaceErrAttr(groups []string, a slog.Attr) slog.Attr { - if len(groups) == 0 && a.Key == "err" { - a.Key = sloggcp.ErrorKey +// requestIDExtractor sets the request XID to a log entry. +func requestIDExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { + if r, ok := ctx.Value(ctxKeyRequestID).(xid.ID); ok { + return []slog.Attr{ + slog.String("request_id", r.String()), + } + } + return nil +} + +type replacer func(groups []string, a slog.Attr) slog.Attr + +func chainReplacers(replacers ...replacer) replacer { + return func(groups []string, a slog.Attr) slog.Attr { + for _, r := range replacers { + a = r(groups, a) + } + return a + } +} + +func errReplacer() replacer { + return func(groups []string, a slog.Attr) slog.Attr { + if len(groups) == 0 && a.Key == "err" { + a.Key = sloggcp.ErrorKey + } + return a } - return a } diff --git a/backend/v3/instrumentation/slog_test.go b/backend/v3/instrumentation/slog_test.go new file mode 100644 index 000000000..6f993afe0 --- /dev/null +++ b/backend/v3/instrumentation/slog_test.go @@ -0,0 +1,138 @@ +package instrumentation + +import ( + "log/slog" + "testing" + + "github.com/stretchr/testify/assert" + old_logging "github.com/zitadel/logging" //nolint:staticcheck + "github.com/zitadel/sloggcp" +) + +func TestLogConfig_SetLegacyConfig(t *testing.T) { + tests := []struct { + name string // description of this test case + lc *old_logging.Config + c *LogConfig + want *LogConfig + }{ + { + name: "nil legacy config does not change log config", + lc: nil, + c: &LogConfig{Level: slog.LevelInfo}, + want: &LogConfig{Level: slog.LevelInfo}, + }, + { + name: "legacy config sets log level when format is disabled", + lc: &old_logging.Config{Level: "debug"}, + c: &LogConfig{Level: slog.LevelInfo}, + want: &LogConfig{Level: slog.LevelDebug}, + }, + { + name: "legacy config does not change log config when format is not disabled", + lc: &old_logging.Config{Level: "debug"}, + c: &LogConfig{Level: slog.LevelInfo, Format: LogFormatJSON}, + want: &LogConfig{Level: slog.LevelInfo, Format: LogFormatJSON}, + }, + { + name: "invalid legacy log level defaults to info", + lc: &old_logging.Config{Level: "invalid"}, + c: &LogConfig{Level: slog.LevelDebug}, + want: &LogConfig{Level: slog.LevelInfo}, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + tt.c.SetLegacyConfig(tt.lc) + assert.Equal(t, tt.want, tt.c) + }) + } +} + +func TestLogConfig_replacer(t *testing.T) { + type args struct { + groups []string + a slog.Attr + } + tests := []struct { + name string // description of this test case + c LogConfig + args args + want slog.Attr + }{ + { + name: "empty config does not change attribute", + c: LogConfig{}, + args: args{ + a: slog.String("key", "value"), + }, + want: slog.String("key", "value"), + }, + { + name: "masking configured key", + c: LogConfig{ + Mask: MaskConfig{ + Keys: []string{"sensitive"}, + Value: "masked", + }, + }, + args: args{ + a: slog.String("sensitive", "value"), + }, + want: slog.String("sensitive", "masked"), + }, + { + name: "masking configured key in any group", + c: LogConfig{ + Mask: MaskConfig{ + Keys: []string{"sensitive"}, + Value: "masked", + }, + }, + args: args{ + groups: []string{"a", "b"}, + a: slog.String("sensitive", "value"), + }, + want: slog.String("sensitive", "masked"), + }, + { + name: "not masking unmatched key", + c: LogConfig{ + Mask: MaskConfig{ + Keys: []string{"sensitive"}, + Value: "masked", + }, + }, + args: args{ + a: slog.String("unmatched", "value"), + }, + want: slog.String("unmatched", "value"), + }, + { + name: "sloggcp replacer", + c: LogConfig{ + Format: LogFormatGCP, + }, + args: args{ + a: slog.Any("level", slog.LevelInfo), + }, + want: slog.String(sloggcp.SeverityKey, sloggcp.InfoSeverity), + }, + { + name: "errReplacer", + c: LogConfig{ + Format: LogFormatGCPErrorReporting, + }, + args: args{ + a: slog.String("err", "some error"), + }, + want: slog.String(sloggcp.ErrorKey, "some error"), + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := tt.c.replacer()(tt.args.groups, tt.args.a) + assert.Equal(t, tt.want, got) + }) + } +} diff --git a/backend/v3/instrumentation/stream.go b/backend/v3/instrumentation/stream.go new file mode 100644 index 000000000..1760beb36 --- /dev/null +++ b/backend/v3/instrumentation/stream.go @@ -0,0 +1,29 @@ +package instrumentation + +import "sync" + +type Stream int + +//go:generate enumer -type=Stream -trimprefix=Stream -transform=snake -text +const ( + StreamRuntime Stream = iota // Top-level commands, such as starting the application or running migrations. + StreamReady // Readiness and liveness checks. + StreamRequest // API request handling. + StreamEventPusher // Event pushing to the database. + StreamEventHandler // Event handling and processing. + StreamQueue // Queue operations and job processing. +) + +var enabledStreams sync.Map + +func EnableStreams(streams ...Stream) { + enabledStreams.Clear() + for _, stream := range streams { + enabledStreams.Store(stream, struct{}{}) + } +} + +func IsStreamEnabled(stream Stream) bool { + _, ok := enabledStreams.Load(stream) + return ok +} diff --git a/backend/v3/instrumentation/stream_enumer.go b/backend/v3/instrumentation/stream_enumer.go new file mode 100644 index 000000000..6463d467d --- /dev/null +++ b/backend/v3/instrumentation/stream_enumer.go @@ -0,0 +1,106 @@ +// Code generated by "enumer -type=Stream -trimprefix=Stream -transform=snake -text"; DO NOT EDIT. + +package instrumentation + +import ( + "fmt" + "strings" +) + +const _StreamName = "runtimereadyrequestevent_pusherevent_handlerqueue" + +var _StreamIndex = [...]uint8{0, 7, 12, 19, 31, 44, 49} + +const _StreamLowerName = "runtimereadyrequestevent_pusherevent_handlerqueue" + +func (i Stream) String() string { + if i < 0 || i >= Stream(len(_StreamIndex)-1) { + return fmt.Sprintf("Stream(%d)", i) + } + return _StreamName[_StreamIndex[i]:_StreamIndex[i+1]] +} + +// An "invalid array index" compiler error signifies that the constant values have changed. +// Re-run the stringer command to generate them again. +func _StreamNoOp() { + var x [1]struct{} + _ = x[StreamRuntime-(0)] + _ = x[StreamReady-(1)] + _ = x[StreamRequest-(2)] + _ = x[StreamEventPusher-(3)] + _ = x[StreamEventHandler-(4)] + _ = x[StreamQueue-(5)] +} + +var _StreamValues = []Stream{StreamRuntime, StreamReady, StreamRequest, StreamEventPusher, StreamEventHandler, StreamQueue} + +var _StreamNameToValueMap = map[string]Stream{ + _StreamName[0:7]: StreamRuntime, + _StreamLowerName[0:7]: StreamRuntime, + _StreamName[7:12]: StreamReady, + _StreamLowerName[7:12]: StreamReady, + _StreamName[12:19]: StreamRequest, + _StreamLowerName[12:19]: StreamRequest, + _StreamName[19:31]: StreamEventPusher, + _StreamLowerName[19:31]: StreamEventPusher, + _StreamName[31:44]: StreamEventHandler, + _StreamLowerName[31:44]: StreamEventHandler, + _StreamName[44:49]: StreamQueue, + _StreamLowerName[44:49]: StreamQueue, +} + +var _StreamNames = []string{ + _StreamName[0:7], + _StreamName[7:12], + _StreamName[12:19], + _StreamName[19:31], + _StreamName[31:44], + _StreamName[44:49], +} + +// StreamString retrieves an enum value from the enum constants string name. +// Throws an error if the param is not part of the enum. +func StreamString(s string) (Stream, error) { + if val, ok := _StreamNameToValueMap[s]; ok { + return val, nil + } + + if val, ok := _StreamNameToValueMap[strings.ToLower(s)]; ok { + return val, nil + } + return 0, fmt.Errorf("%s does not belong to Stream values", s) +} + +// StreamValues returns all values of the enum +func StreamValues() []Stream { + return _StreamValues +} + +// StreamStrings returns a slice of all String values of the enum +func StreamStrings() []string { + strs := make([]string, len(_StreamNames)) + copy(strs, _StreamNames) + return strs +} + +// IsAStream returns "true" if the value is listed in the enum definition. "false" otherwise +func (i Stream) IsAStream() bool { + for _, v := range _StreamValues { + if i == v { + return true + } + } + return false +} + +// MarshalText implements the encoding.TextMarshaler interface for Stream +func (i Stream) MarshalText() ([]byte, error) { + return []byte(i.String()), nil +} + +// UnmarshalText implements the encoding.TextUnmarshaler interface for Stream +func (i *Stream) UnmarshalText(text []byte) error { + var err error + *i, err = StreamString(string(text)) + return err +} diff --git a/backend/v3/instrumentation/stream_test.go b/backend/v3/instrumentation/stream_test.go new file mode 100644 index 000000000..7b2c40579 --- /dev/null +++ b/backend/v3/instrumentation/stream_test.go @@ -0,0 +1,13 @@ +package instrumentation + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestStream(t *testing.T) { + EnableStreams(StreamRuntime) + assert.True(t, IsStreamEnabled(StreamRuntime)) + assert.False(t, IsStreamEnabled(StreamQueue)) +} diff --git a/backend/v3/instrumentation/tracing.go b/backend/v3/instrumentation/tracing.go index 179147338..57426c411 100644 --- a/backend/v3/instrumentation/tracing.go +++ b/backend/v3/instrumentation/tracing.go @@ -2,6 +2,7 @@ package instrumentation import ( "context" + "errors" "fmt" "net/http" "os" @@ -9,6 +10,7 @@ import ( google_trace "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace" "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" "go.opentelemetry.io/otel/exporters/stdout/stdouttrace" @@ -16,7 +18,7 @@ import ( sdk_trace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/trace" - "github.com/zitadel/zitadel/internal/api/grpc/gerrors" + "github.com/zitadel/zitadel/internal/zerrors" ) type TraceConfig struct { @@ -119,10 +121,16 @@ func (s *Span) SetStatusByError(err error) { } if err != nil { s.span.RecordError(err) + s.span.SetStatus(codes.Error, err.Error()) + } + var zerr *zerrors.ZitadelError + if errors.As(err, &zerr) { + s.span.SetAttributes( + attribute.Stringer("error_kind", zerr.Kind), + attribute.String("error_msg", zerr.Message), + attribute.String("error_id", zerr.ID), + ) } - - code, msg, id := gerrors.ExtractZITADELError(err) - s.span.SetAttributes(attribute.Int("grpc_code", int(code)), attribute.String("grpc_msg", msg), attribute.String("error_id", id)) } func newTracerProvider(ctx context.Context, cfg TraceConfig, resource *resource.Resource) (_ *sdk_trace.TracerProvider, err error) { diff --git a/backend/v3/instrumentation/tracing/http_handler.go b/backend/v3/instrumentation/tracing/http_handler.go deleted file mode 100644 index 408e3a101..000000000 --- a/backend/v3/instrumentation/tracing/http_handler.go +++ /dev/null @@ -1,23 +0,0 @@ -package tracing - -import ( - "net/http" - - "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" - "go.opentelemetry.io/otel" - - "github.com/zitadel/zitadel/backend/v3/instrumentation" -) - -func NewHandler(handler http.Handler, ignoredPrefix ...string) http.Handler { - return otelhttp.NewHandler(handler, - "zitadel", - otelhttp.WithFilter(instrumentation.RequestFilter(ignoredPrefix...)), - otelhttp.WithPublicEndpoint(), - otelhttp.WithSpanNameFormatter(spanNameFormatter), - otelhttp.WithMeterProvider(otel.GetMeterProvider())) -} - -func spanNameFormatter(_ string, r *http.Request) string { - return r.URL.Path -} diff --git a/backend/v3/storage/database/events_testing/events_test.go b/backend/v3/storage/database/events_testing/events_test.go index 6cc43a6c3..3795ac113 100644 --- a/backend/v3/storage/database/events_testing/events_test.go +++ b/backend/v3/storage/database/events_testing/events_test.go @@ -52,8 +52,8 @@ var ( SystemClient system.SystemServiceClient OrgClient v2beta_org.OrganizationServiceClient ProjectClient v2beta_project.ProjectServiceClient - SessionClient session.SessionServiceClient - UserClient user.UserServiceClient + SessionClient session.SessionServiceClient + UserClient user.UserServiceClient AdminClient admin.AdminServiceClient MgmtClient mgmt.ManagementServiceClient AuthorizationClient authorization.AuthorizationServiceClient diff --git a/cmd/build/info.go b/cmd/build/info.go index 8d0b18931..005ce90be 100644 --- a/cmd/build/info.go +++ b/cmd/build/info.go @@ -1,9 +1,8 @@ package build import ( + "log/slog" "time" - - "github.com/zitadel/logging" ) // These variables are set via ldflags in the Makefile @@ -21,12 +20,12 @@ func init() { var err error dateTime, err = time.Parse(time.RFC3339, date) if err != nil { - logging.WithError(err).Warn("could not parse build date, using current time instead") + slog.Warn("could not parse build date, using current time instead", "err", err) dateTime = time.Now() date = dateTime.Format(time.RFC3339) } if version == "" { - logging.Warn("no build version set, using timestamp as version") + slog.Warn("no build version set, using timestamp as version") version = date } } diff --git a/cmd/defaults.yaml b/cmd/defaults.yaml index 1b78b9b5c..d89745e84 100644 --- a/cmd/defaults.yaml +++ b/cmd/defaults.yaml @@ -46,14 +46,36 @@ Instrumentation: Log: # Log lines lower than this level are not emitted. Level: "INFO" # ZITADEL_INSTRUMENTATION_LOG_LEVEL + # Streams enable logging for specific parts of the application. + Streams: # ZITADEL_INSTRUMENTATION_LOG_STREAMS (comma separated list) + - runtime # General runtime logs, such as startup and shutdown messages. + - request # Logs for incoming API and HTTP requests. + - event_handler # Logs for event handling in projections. + - queue # Logs for the job queue processing. + #- event_pusher # Logs for event pushing to the database. Warning: contains sensitive information. + # Mask replaces sensitive information with Value in logs matched by Key + Mask: + # Keys are the attribute keys to be masked in logs. + # Keys are unqualified attribute names and apply to all attributes with the specified name, + # regardless of their position in the attribute hierarchy. + # Eg. "some_key" matches "some_key" and "parent.some_key" etc. + # If the matched log attribute is a nested object or array, + # the entire structure is replaced with the specified Value. + Keys: # ZITADEL_INSTRUMENTATION_LOG_MASK_KEYS (comma separated list) + # - "first_name" + # - "last_name" + # Value is the string that replaces the original value of masked attributes. + Value: "****" # ZITADEL_INSTRUMENTATION_LOG_MASK_VALUE # Enable printing structured logs to standard error in the specified format. + # When disabled, the legacy Log configuration is used. + # Important: when legacy Log is customized, please add a format and customize before upgrading to v5 # The following formats are supported: - # - "disabled": Disables logging + # - "disabled": Disables logging (or fallback to legacy Log config) # - "text": Logs are printed on StdErr as human-readable text # - "json": Logs are printed on StdErr as JSON objects - # - "gcp": JSON formatted logs compatible with Google Cloud Platform logging. Need to configure GoogleProjectID below! - # - "gcp_error_reporting": JSON formatted logs compatible with Google Cloud Platform Error Reporting. Need to configure GoogleProjectID below! - Format: "text" # ZITADEL_INSTRUMENTATION_LOG_STDERR + # - "gcp": JSON formatted logs compatible with Google Cloud Platform logging. + # - "gcp_error_reporting": JSON formatted logs compatible with Google Cloud Platform Error Reporting. + Format: "disabled" # ZITADEL_INSTRUMENTATION_LOG_STDERR # Adds the source file and line number where the log line was emitted. # Not to be confused with the source of an error. AddSource: true # ZITADEL_INSTRUMENTATION_LOG_ADDSOURCE diff --git a/cmd/initialise/config.go b/cmd/initialise/config.go index 899018ddc..140886baa 100644 --- a/cmd/initialise/config.go +++ b/cmd/initialise/config.go @@ -1,34 +1,54 @@ package initialise import ( - "github.com/mitchellh/mapstructure" - "github.com/spf13/viper" - "github.com/zitadel/logging" + "errors" + "fmt" + "github.com/mitchellh/mapstructure" + "github.com/spf13/cobra" + "github.com/spf13/viper" + old_logging "github.com/zitadel/logging" //nolint:staticcheck + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/id" ) type Config struct { - Database database.Config - Machine *id.Config - Log *logging.Config + Instrumentation instrumentation.Config + Database database.Config + Machine *id.Config + Log *old_logging.Config } -func MustNewConfig(v *viper.Viper) *Config { +func NewConfig(cmd *cobra.Command, v *viper.Viper) (*Config, instrumentation.ShutdownFunc, error) { config := new(Config) err := v.Unmarshal(config, viper.DecodeHook(mapstructure.ComposeDecodeHookFunc( database.DecodeHook(false), + mapstructure.StringToTimeDurationHookFunc(), mapstructure.TextUnmarshallerHookFunc(), )), ) - logging.OnError(err).Fatal("unable to read config") + if err != nil { + return nil, nil, fmt.Errorf("unable to read config: %w", err) + } + + config.Instrumentation.Log.SetLegacyConfig(config.Log) + shutdown, err := instrumentation.Start(cmd.Context(), config.Instrumentation) + if err != nil { + return nil, nil, fmt.Errorf("unable to start instrumentation: %w", err) + } + cmd.SetContext(logging.NewCtx(cmd.Context(), logging.StreamRuntime)) err = config.Log.SetLogger() - logging.OnError(err).Fatal("unable to set logger") + if err != nil { + err = errors.Join(err, shutdown(cmd.Context())) + return nil, nil, fmt.Errorf("unable to set logger: %w", err) + } id.Configure(config.Machine) - return config + return config, shutdown, nil } diff --git a/cmd/initialise/init.go b/cmd/initialise/init.go index 1d51f465f..f8ec112a6 100644 --- a/cmd/initialise/init.go +++ b/cmd/initialise/init.go @@ -3,13 +3,13 @@ package initialise import ( "context" "embed" + "errors" "fmt" - "log/slog" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -47,11 +47,15 @@ The user provided by flags needs privileges to `, RunE: func(cmd *cobra.Command, args []string) (err error) { defer func() { - if err != nil { - slog.Error("zitadel init command failed", "err", err) - } + logging.OnError(cmd.Context(), err).Error("zitadel init command failed") + }() + config, shutdown, err := NewConfig(cmd, viper.GetViper()) + if err != nil { + return err + } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) }() - config := MustNewConfig(viper.GetViper()) return InitAll(cmd.Context(), config) }, @@ -79,7 +83,7 @@ func InitAll(ctx context.Context, config *Config) error { } func initialise(ctx context.Context, config database.Config, steps ...func(context.Context, *database.DB) error) error { - logging.Info("initialization started") + logging.Info(ctx, "initialization started") err := ReadStmts() if err != nil { diff --git a/cmd/initialise/verify_database.go b/cmd/initialise/verify_database.go index 62fbd9b40..4b108706f 100644 --- a/cmd/initialise/verify_database.go +++ b/cmd/initialise/verify_database.go @@ -4,12 +4,13 @@ import ( "context" "database/sql" _ "embed" + "errors" "fmt" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -27,11 +28,19 @@ The user provided by flags needs privileges to - see other users and create a new one if the user does not exist - grant all rights of the ZITADEL database to the user created if not yet set `, - Run: func(cmd *cobra.Command, args []string) { - config := MustNewConfig(viper.GetViper()) + RunE: func(cmd *cobra.Command, args []string) (err error) { + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel init verify database command failed") + }() + config, shutdown, err := NewConfig(cmd, viper.GetViper()) + if err != nil { + return err + } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) + }() - err := initialise(cmd.Context(), config.Database, VerifyDatabase(config.Database.DatabaseName())) - logging.OnError(err).Fatal("unable to initialize the database") + return initialise(cmd.Context(), config.Database, VerifyDatabase(config.Database.DatabaseName())) }, } } @@ -46,10 +55,10 @@ func VerifyDatabase(databaseName string) func(context.Context, *database.DB) err return fmt.Errorf("unable to get current database: %w", err) } if currentDatabase == databaseName { - logging.WithFields("database", databaseName).Info("database is same as config.database.postgres.admin.ExistingDatabase, skipping creation") + logging.Info(ctx, "database is same as config.database.postgres.admin.ExistingDatabase, skipping creation", "database", databaseName) return nil } - logging.WithFields("database", databaseName).Info("verify database") + logging.Info(ctx, "verify database", "database", databaseName) return exec(ctx, db, fmt.Sprintf(databaseStmt, databaseName), []string{dbAlreadyExistsCode}) } diff --git a/cmd/initialise/verify_grant.go b/cmd/initialise/verify_grant.go index 5f87135d7..79a8fb6b9 100644 --- a/cmd/initialise/verify_grant.go +++ b/cmd/initialise/verify_grant.go @@ -4,12 +4,13 @@ import ( "context" "database/sql" _ "embed" + "errors" "fmt" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -22,11 +23,19 @@ func newGrant() *cobra.Command { Prerequisites: - postgreSQL `, - Run: func(cmd *cobra.Command, args []string) { - config := MustNewConfig(viper.GetViper()) + RunE: func(cmd *cobra.Command, args []string) (err error) { + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel verify grant command failed") + }() + config, shutdown, err := NewConfig(cmd, viper.GetViper()) + if err != nil { + return err + } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) + }() - err := initialise(cmd.Context(), config.Database, VerifyGrant(config.Database.DatabaseName(), config.Database.Username())) - logging.OnError(err).Fatal("unable to set grant") + return initialise(cmd.Context(), config.Database, VerifyGrant(config.Database.DatabaseName(), config.Database.Username())) }, } } @@ -41,10 +50,10 @@ func VerifyGrant(databaseName, username string) func(context.Context, *database. return fmt.Errorf("unable to get current user: %w", err) } if currentUser == username { - logging.WithFields("username", username).Info("config.database.postgres.user.username is same as config.database.postgres.admin.username, skipping grant") + logging.Info(ctx, "config.database.postgres.user.username is same as config.database.postgres.admin.username, skipping grant", "username", username) return nil } - logging.WithFields("user", username, "database", databaseName).Info("verify grant") + logging.Info(ctx, "verify grant", "user", username, "database", databaseName) return exec(ctx, db, fmt.Sprintf(grantStmt, databaseName, username), nil) } diff --git a/cmd/initialise/verify_user.go b/cmd/initialise/verify_user.go index bf6e98306..d821216f4 100644 --- a/cmd/initialise/verify_user.go +++ b/cmd/initialise/verify_user.go @@ -4,12 +4,13 @@ import ( "context" "database/sql" _ "embed" + "errors" "fmt" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -27,11 +28,19 @@ The user provided by flags needs privileges to - see other users and create a new one if the user does not exist - grant all rights of the ZITADEL database to the user created if not yet set `, - Run: func(cmd *cobra.Command, args []string) { - config := MustNewConfig(viper.GetViper()) + RunE: func(cmd *cobra.Command, args []string) (err error) { + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel verify user command failed") + }() + config, shutdown, err := NewConfig(cmd, viper.GetViper()) + if err != nil { + return err + } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) + }() - err := initialise(cmd.Context(), config.Database, VerifyUser(config.Database.Username(), config.Database.Password())) - logging.OnError(err).Fatal("unable to init user") + return initialise(cmd.Context(), config.Database, VerifyUser(config.Database.Username(), config.Database.Password())) }, } } @@ -46,11 +55,10 @@ func VerifyUser(username, password string) func(context.Context, *database.DB) e return fmt.Errorf("unable to get current user: %w", err) } if currentUser == username { - logging.WithFields("username", username).Info("config.database.postgres.user.username is same as config.database.postgres.admin.username, skipping create user") + logging.Info(ctx, "config.database.postgres.user.username is same as config.database.postgres.admin.username, skipping create user", "username", username) return nil } - logging.WithFields("username", username).Info("verify user") - + logging.Info(ctx, "verify user", "username", username) if password != "" { createUserStmt += " WITH PASSWORD '" + password + "'" } diff --git a/cmd/initialise/verify_zitadel.go b/cmd/initialise/verify_zitadel.go index 78f28809c..2a5d3f41e 100644 --- a/cmd/initialise/verify_zitadel.go +++ b/cmd/initialise/verify_zitadel.go @@ -4,12 +4,13 @@ import ( "context" "database/sql" _ "embed" + "errors" "fmt" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" es_v3 "github.com/zitadel/zitadel/internal/eventstore/v3" ) @@ -23,10 +24,18 @@ func newZitadel() *cobra.Command { Prerequisites: - postgreSQL with user and database `, - Run: func(cmd *cobra.Command, args []string) { - config := MustNewConfig(viper.GetViper()) - err := verifyZitadel(cmd.Context(), config.Database) - logging.OnError(err).Fatal("unable to init zitadel") + RunE: func(cmd *cobra.Command, args []string) (err error) { + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel verify zitadel command failed") + }() + config, shutdown, err := NewConfig(cmd, viper.GetViper()) + if err != nil { + return err + } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) + }() + return verifyZitadel(cmd.Context(), config.Database) }, } } @@ -43,32 +52,32 @@ func VerifyZitadel(ctx context.Context, db *database.DB, config database.Config) } defer conn.Close() - logging.WithFields().Info("verify system") + logging.Info(ctx, "verify system") if err := exec(ctx, conn, fmt.Sprintf(createSystemStmt, config.Username()), nil); err != nil { return err } - logging.WithFields().Info("verify encryption keys") + logging.Info(ctx, "verify encryption keys") if err := createEncryptionKeys(ctx, conn); err != nil { return err } - logging.WithFields().Info("verify projections") + logging.Info(ctx, "verify projections") if err := exec(ctx, conn, fmt.Sprintf(createProjectionsStmt, config.Username()), nil); err != nil { return err } - logging.WithFields().Info("verify eventstore") + logging.Info(ctx, "verify eventstore") if err := exec(ctx, conn, fmt.Sprintf(createEventstoreStmt, config.Username()), nil); err != nil { return err } - logging.WithFields().Info("verify events tables") + logging.Info(ctx, "verify events tables") if err := createEvents(ctx, conn); err != nil { return err } - logging.WithFields().Info("verify unique constraints") + logging.Info(ctx, "verify unique constraints") if err := exec(ctx, conn, createUniqueConstraints, nil); err != nil { return err } @@ -77,7 +86,7 @@ func VerifyZitadel(ctx context.Context, db *database.DB, config database.Config) } func verifyZitadel(ctx context.Context, config database.Config) error { - logging.WithFields("database", config.DatabaseName()).Info("verify zitadel") + logging.Info(ctx, "verify zitadel", "database", config.DatabaseName()) db, err := database.Connect(config, false) if err != nil { @@ -98,7 +107,7 @@ func createEncryptionKeys(ctx context.Context, db database.Beginner) error { } if _, err = tx.Exec(createEncryptionKeysStmt); err != nil { rollbackErr := tx.Rollback() - logging.OnError(rollbackErr).Error("rollback failed") + logging.WithError(ctx, rollbackErr).Error("rollback failed") return err } @@ -113,7 +122,7 @@ func createEvents(ctx context.Context, conn *sql.Conn) (err error) { defer func() { if err != nil { rollbackErr := tx.Rollback() - logging.OnError(rollbackErr).Error("rollback failed") + logging.WithError(ctx, rollbackErr).Error("rollback failed") return } err = tx.Commit() diff --git a/cmd/mirror/auth.go b/cmd/mirror/auth.go index 8131eec77..ddefe01c6 100644 --- a/cmd/mirror/auth.go +++ b/cmd/mirror/auth.go @@ -11,8 +11,8 @@ import ( "github.com/jackc/pgx/v5/stdlib" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -24,7 +24,10 @@ func authCmd() *cobra.Command { ZITADEL needs to be initialized and set up with the --for-mirror flag Only auth requests are mirrored`, RunE: func(cmd *cobra.Command, args []string) (err error) { - config, shutdown, err := mustNewMigrationConfig(cmd.Context(), viper.GetViper()) + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel mirror auth command failed") + }() + config, shutdown, err := newMigrationConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -43,11 +46,11 @@ Only auth requests are mirrored`, func copyAuth(ctx context.Context, config *Migration) { sourceClient, err := database.Connect(config.Source, false) - logging.OnError(err).Fatal("unable to connect to source database") + logging.OnError(ctx, err).Fatal("unable to connect to source database") defer sourceClient.Close() destClient, err := database.Connect(config.Destination, false) - logging.OnError(err).Fatal("unable to connect to destination database") + logging.OnError(ctx, err).Fatal("unable to connect to destination database") defer destClient.Close() copyAuthRequests(ctx, sourceClient, destClient, config.MaxAuthRequestAge) @@ -56,12 +59,12 @@ func copyAuth(ctx context.Context, config *Migration) { func copyAuthRequests(ctx context.Context, source, dest *database.DB, maxAuthRequestAge time.Duration) { start := time.Now() - logging.Info("creating index on auth.auth_requests.change_date to speed up copy in source database") + logging.Info(ctx, "creating index on auth.auth_requests.change_date to speed up copy in source database") _, err := source.ExecContext(ctx, "CREATE INDEX CONCURRENTLY IF NOT EXISTS auth_requests_change_date ON auth.auth_requests (change_date)") - logging.OnError(err).Fatal("unable to create index on auth.auth_requests.change_date") + logging.OnError(ctx, err).Fatal("unable to create index on auth.auth_requests.change_date") sourceConn, err := source.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire connection") + logging.OnError(ctx, err).Fatal("unable to acquire connection") defer sourceConn.Close() r, w := io.Pipe() @@ -78,7 +81,7 @@ func copyAuthRequests(ctx context.Context, source, dest *database.DB, maxAuthReq }() destConn, err := dest.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire connection") + logging.OnError(ctx, err).Fatal("unable to acquire connection") defer destConn.Close() var affected int64 @@ -97,7 +100,7 @@ func copyAuthRequests(ctx context.Context, source, dest *database.DB, maxAuthReq return err }) - logging.OnError(err).Fatal("unable to copy auth requests to destination") - logging.OnError(<-errs).Fatal("unable to copy auth requests from source") - logging.WithFields("took", time.Since(start), "count", affected).Info("auth requests migrated") + logging.OnError(ctx, err).Fatal("unable to copy auth requests to destination") + logging.OnError(ctx, <-errs).Fatal("unable to copy auth requests from source") + logging.Info(ctx, "auth requests migrated", "took", time.Since(start), "count", affected) } diff --git a/cmd/mirror/config.go b/cmd/mirror/config.go index 648ea6ef5..495ec91e9 100644 --- a/cmd/mirror/config.go +++ b/cmd/mirror/config.go @@ -1,16 +1,17 @@ package mirror import ( - "context" _ "embed" "fmt" "time" "github.com/mitchellh/mapstructure" + "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + old_logging "github.com/zitadel/logging" //nolint:staticcheck "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/hooks" "github.com/zitadel/zitadel/internal/actions" internal_authz "github.com/zitadel/zitadel/internal/api/authz" @@ -28,7 +29,7 @@ type Migration struct { EventBulkSize uint32 MaxAuthRequestAge time.Duration - Log *logging.Config + Log *old_logging.Config Machine *id.Config Instrumentation instrumentation.Config Metrics instrumentation.LegacyMetricConfig @@ -39,39 +40,50 @@ var ( defaultConfig []byte ) -func mustNewMigrationConfig(ctx context.Context, v *viper.Viper) (*Migration, instrumentation.ShutdownFunc, error) { +func newMigrationConfig(cmd *cobra.Command, v *viper.Viper) (*Migration, instrumentation.ShutdownFunc, error) { config := new(Migration) - mustNewConfig(v, config) - - shutdown, err := instrumentation.Start(ctx, config.Instrumentation) + err := newConfig(v, config) if err != nil { - return nil, nil, fmt.Errorf("unable to start instrumentation: %w", err) + return nil, nil, err } - - // Legacy logger - err = config.Log.SetLogger() + shutdown, err := startInstrumentation(cmd, config.Instrumentation, config.Log) if err != nil { - return nil, nil, fmt.Errorf("unable to set logger: %w", err) + return nil, nil, err } - id.Configure(config.Machine) - return config, shutdown, nil } -func mustNewProjectionsConfig(v *viper.Viper) *ProjectionsConfig { +func newProjectionsConfig(cmd *cobra.Command, v *viper.Viper) (*ProjectionsConfig, instrumentation.ShutdownFunc, error) { config := new(ProjectionsConfig) - mustNewConfig(v, config) - - err := config.Log.SetLogger() - logging.OnError(err).Fatal("unable to set logger") - + err := newConfig(v, config) + if err != nil { + return nil, nil, err + } + shutdown, err := startInstrumentation(cmd, config.Instrumentation, config.Log) + if err != nil { + return nil, nil, err + } id.Configure(config.Machine) - - return config + return config, shutdown, nil } -func mustNewConfig(v *viper.Viper, config any) { +func startInstrumentation(cmd *cobra.Command, cfg instrumentation.Config, logConfig *old_logging.Config) (instrumentation.ShutdownFunc, error) { + cfg.Log.SetLegacyConfig(logConfig) + shutdown, err := instrumentation.Start(cmd.Context(), cfg) + if err != nil { + return nil, fmt.Errorf("unable to start instrumentation: %w", err) + } + // Legacy logger + err = logConfig.SetLogger() + if err != nil { + return nil, fmt.Errorf("unable to set logger: %w", err) + } + cmd.SetContext(logging.NewCtx(cmd.Context(), logging.StreamRuntime)) + return shutdown, nil +} + +func newConfig(v *viper.Viper, config any) error { err := v.Unmarshal(config, viper.DecodeHook(mapstructure.ComposeDecodeHookFunc( hooks.SliceTypeStringDecode[*domain.CustomMessageText], @@ -91,5 +103,8 @@ func mustNewConfig(v *viper.Viper, config any) { mapstructure.TextUnmarshallerHookFunc(), )), ) - logging.OnError(err).Fatal("unable to read default config") + if err != nil { + return fmt.Errorf("unable to decode config: %w", err) + } + return nil } diff --git a/cmd/mirror/defaults.yaml b/cmd/mirror/defaults.yaml index d6fbbb433..d7b7ea71e 100644 --- a/cmd/mirror/defaults.yaml +++ b/cmd/mirror/defaults.yaml @@ -46,14 +46,36 @@ Instrumentation: Log: # Log lines lower than this level are not emitted. Level: "INFO" # ZITADEL_INSTRUMENTATION_LOG_LEVEL + # Streams enable logging for specific parts of the application. + Streams: # ZITADEL_INSTRUMENTATION_LOG_STREAMS (comma separated list) + - runtime # General runtime logs, such as startup and shutdown messages. + - request # Logs for incoming API and HTTP requests. + - event_handler # Logs for event handling in projections. + - queue # Logs for the job queue processing. + # - event_pusher # Logs for event pushing to the database. Warning: contains sensitive information. + # Mask replaces sensitive information with Value in logs matched by Key + Mask: + # Keys are the attribute keys to be masked in logs. + # Keys are unqualified attribute names and apply to all attributes with the specified name, + # regardless of their position in the attribute hierarchy. + # Eg. "some_key" matches "some_key" and "parent.some_key" etc. + # If the matched log attribute is a nested object or array, + # the entire structure is replaced with the specified Value. + Keys: # ZITADEL_INSTRUMENTATION_LOG_MASK_KEYS (comma separated list) + # - "first_name" + # - "last_name" + # Value is the string that replaces the original value of masked attributes. + Value: "****" # ZITADEL_INSTRUMENTATION_LOG_MASK_VALUE # Enable printing structured logs to standard error in the specified format. + # When disabled, the legacy Log configuration is used. + # Important: when legacy Log is customized, please add a format and customize before upgrading to v5 # The following formats are supported: - # - "disabled": Disables logging + # - "disabled": Disables logging (or fallback to legacy Log config) # - "text": Logs are printed on StdErr as human-readable text # - "json": Logs are printed on StdErr as JSON objects - # - "gcp": JSON formatted logs compatible with Google Cloud Platform logging. Need to configure GoogleProjectID below! - # - "gcp_error_reporting": JSON formatted logs compatible with Google Cloud Platform Error Reporting. Need to configure GoogleProjectID below! - Format: "text" # ZITADEL_INSTRUMENTATION_LOG_STDERR + # - "gcp": JSON formatted logs compatible with Google Cloud Platform logging. + # - "gcp_error_reporting": JSON formatted logs compatible with Google Cloud Platform Error Reporting. + Format: "disabled" # ZITADEL_INSTRUMENTATION_LOG_STDERR # Adds the source file and line number where the log line was emitted. # Not to be confused with the source of an error. AddSource: true # ZITADEL_INSTRUMENTATION_LOG_ADDSOURCE @@ -63,6 +85,10 @@ Instrumentation: ReportLocation: true # ZITADEL_INSTRUMENTATION_LOG_ERRORS_REPORTLOCATION # Adds stack traces to logged errors. StackTrace: false # ZITADEL_INSTRUMENTATION_LOG_ERRORS_STACKTRACE + # Exporter configures where the OTEL formatted logs are exported to. + # You typically want to disable this unless you have a OTEL collector setup. + # Enabling stdOut or stdErr here will result in duplicate logs (of different format) + # if there's also a Format set above. Exporter: # The following exporter types are supported: # - "none": Disables OTEL log exporter diff --git a/cmd/mirror/event_store.go b/cmd/mirror/event_store.go index f6b9bccb6..6cb040350 100644 --- a/cmd/mirror/event_store.go +++ b/cmd/mirror/event_store.go @@ -13,8 +13,8 @@ import ( "github.com/shopspring/decimal" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" db "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/database/dialect" "github.com/zitadel/zitadel/internal/id" @@ -34,7 +34,11 @@ func eventstoreCmd() *cobra.Command { ZITADEL needs to be initialized and set up with the --for-mirror flag Migrate only copies events2 and unique constraints`, RunE: func(cmd *cobra.Command, args []string) (err error) { - config, shutdown, err := mustNewMigrationConfig(cmd.Context(), viper.GetViper()) + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel mirror eventstore command failed") + }() + + config, shutdown, err := newMigrationConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -54,49 +58,48 @@ Migrate only copies events2 and unique constraints`, func copyEventstore(ctx context.Context, config *Migration) { sourceClient, err := db.Connect(config.Source, false) - logging.OnError(err).Fatal("unable to connect to source database") + logging.OnError(ctx, err).Fatal("unable to connect to source database") defer sourceClient.Close() destClient, err := db.Connect(config.Destination, false) - logging.OnError(err).Fatal("unable to connect to destination database") + logging.OnError(ctx, err).Fatal("unable to connect to destination database") defer destClient.Close() copyEvents(ctx, sourceClient, destClient, config.EventBulkSize) copyUniqueConstraints(ctx, sourceClient, destClient) } -func positionQuery(db *db.DB) string { +func positionQuery(db *db.DB) (string, error) { switch db.Type() { case dialect.DatabaseTypePostgres: - return "SELECT EXTRACT(EPOCH FROM clock_timestamp())" + return "SELECT EXTRACT(EPOCH FROM clock_timestamp())", nil case dialect.DatabaseTypeCockroach: - return "SELECT cluster_logical_timestamp()" + return "SELECT cluster_logical_timestamp()", nil default: - logging.WithFields("db_type", db.Type()).Fatal("database type not recognized") - return "" + return "", errors.New("database type not recognized") } } func copyEvents(ctx context.Context, source, dest *db.DB, bulkSize uint32) { - logging.Info("starting to copy events") + logging.Info(ctx, "starting to copy events") start := time.Now() reader, writer := io.Pipe() migrationID, err := id.SonyFlakeGenerator().Next() - logging.OnError(err).Fatal("unable to generate migration id") + logging.OnError(ctx, err).Fatal("unable to generate migration id") sourceConn, err := source.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire source connection") + logging.OnError(ctx, err).Fatal("unable to acquire source connection") destConn, err := dest.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire dest connection") + logging.OnError(ctx, err).Fatal("unable to acquire dest connection") destinationES := eventstore.NewEventstoreFromOne(postgres.New(dest, &postgres.Config{ MaxRetries: 3, })) previousMigration, err := queryLastSuccessfulMigration(ctx, destinationES, source.DatabaseName()) - logging.OnError(err).Fatal("unable to query latest successful migration") + logging.OnError(ctx, err).Fatal("unable to query latest successful migration") var maxPosition decimal.Decimal err = source.QueryRowContext(ctx, @@ -105,9 +108,8 @@ func copyEvents(ctx context.Context, source, dest *db.DB, bulkSize uint32) { }, "SELECT MAX(position) FROM eventstore.events2 "+instanceClause(), ) - logging.OnError(err).Fatal("unable to query max position from source") - - logging.WithFields("from", previousMigration.Position, "to", maxPosition).Info("start event migration") + logging.OnError(ctx, err).Fatal("unable to query max position from source") + logging.Info(ctx, "start event migration", "from", previousMigration.Position, "to", maxPosition) nextPos := make(chan bool, 1) pos := make(chan decimal.Decimal, 1) @@ -140,10 +142,10 @@ func copyEvents(ctx context.Context, source, dest *db.DB, bulkSize uint32) { if err != nil { return zerrors.ThrowUnknownf(err, "MIGRA-KTuSq", "unable to copy events from source during iteration %d", i) } - logging.WithFields("batch_count", i).Info("batch of events copied") + logging.Info(ctx, "batch of events copied", "batch_count", i) if tag.RowsAffected() < int64(bulkSize) { - logging.WithFields("batch_count", i).Info("last batch of events copied") + logging.Info(ctx, "last batch of events copied", "batch_count", i) return nil } @@ -162,12 +164,18 @@ func copyEvents(ctx context.Context, source, dest *db.DB, bulkSize uint32) { defer close(pos) for range nextPos { var position decimal.Decimal - err := dest.QueryRowContext( + query, err := positionQuery(dest) + if err != nil { + errs <- zerrors.ThrowUnknown(err, "MIGRA-Hy6t3", "unable to generate position query") + return + } + + err = dest.QueryRowContext( ctx, func(row *sql.Row) error { return row.Scan(&position) }, - positionQuery(dest), + query, ) if err != nil { errs <- zerrors.ThrowUnknown(err, "MIGRA-kMyPH", "unable to query next position") @@ -187,7 +195,7 @@ func copyEvents(ctx context.Context, source, dest *db.DB, bulkSize uint32) { pgErr := new(pgconn.PgError) errors.As(err, &pgErr) - logging.WithError(err).WithField("pg_err_details", pgErr.Detail).Error("unable to copy events into destination") + logging.WithError(ctx, err).Error("unable to copy events into destination", "pg_err_details", pgErr.Detail) return zerrors.ThrowUnknown(err, "MIGRA-DTHi7", "unable to copy events into destination") } @@ -197,7 +205,7 @@ func copyEvents(ctx context.Context, source, dest *db.DB, bulkSize uint32) { close(errs) writeCopyEventsDone(ctx, destinationES, migrationID, source.DatabaseName(), maxPosition, errs) - logging.WithFields("took", time.Since(start), "count", eventCount).Info("events migrated") + logging.Info(ctx, "events migrated", "took", time.Since(start), "count", eventCount) } func writeCopyEventsDone(ctx context.Context, es *eventstore.EventStore, id, source string, position decimal.Decimal, errs <-chan error) { @@ -208,24 +216,24 @@ func writeCopyEventsDone(ctx context.Context, es *eventstore.EventStore, id, sou err := errors.Join(joinedErrs...) if err != nil { - logging.WithError(err).Error("unable to mirror events") + logging.WithError(ctx, err).Error("unable to mirror events") err := writeMigrationFailed(ctx, es, id, source, err) - logging.OnError(err).Fatal("unable to write failed event") + logging.OnError(ctx, err).Fatal("unable to write failed event") return } err = writeMigrationSucceeded(ctx, es, id, source, position) - logging.OnError(err).Fatal("unable to write failed event") + logging.OnError(ctx, err).Fatal("unable to write succeeded event") } func copyUniqueConstraints(ctx context.Context, source, dest *db.DB) { - logging.Info("starting to copy unique constraints") + logging.Info(ctx, "starting to copy unique constraints") start := time.Now() reader, writer := io.Pipe() errs := make(chan error, 1) sourceConn, err := source.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire source connection") + logging.OnError(ctx, err).Fatal("unable to acquire source connection") go func() { err := sourceConn.Raw(func(driverConn interface{}) error { @@ -243,7 +251,7 @@ func copyUniqueConstraints(ctx context.Context, source, dest *db.DB) { }() destConn, err := dest.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire dest connection") + logging.OnError(ctx, err).Fatal("unable to acquire dest connection") var eventCount int64 err = destConn.Raw(func(driverConn interface{}) error { @@ -265,7 +273,7 @@ func copyUniqueConstraints(ctx context.Context, source, dest *db.DB) { return err }) - logging.OnError(err).Fatal("unable to copy unique constraints to destination") - logging.OnError(<-errs).Fatal("unable to copy unique constraints from source") - logging.WithFields("took", time.Since(start), "count", eventCount).Info("unique constraints migrated") + logging.OnError(ctx, err).Fatal("unable to copy unique constraints to destination") + logging.OnError(ctx, <-errs).Fatal("unable to copy unique constraints from source") + logging.Info(ctx, "unique constraints migrated", "took", time.Since(start), "count", eventCount) } diff --git a/cmd/mirror/mirror.go b/cmd/mirror/mirror.go index 1d7cc297f..fdffc9678 100644 --- a/cmd/mirror/mirror.go +++ b/cmd/mirror/mirror.go @@ -5,13 +5,12 @@ import ( _ "embed" "errors" "fmt" - "log/slog" "strings" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/key" ) @@ -37,24 +36,28 @@ Order of execution: 3. mirror event store tables 4. recompute projections 5. verify`, - PersistentPreRun: func(cmd *cobra.Command, args []string) { - err := viper.MergeConfig(bytes.NewBuffer(defaultConfig)) - logging.OnError(err).Fatal("unable to read default config") + PersistentPreRunE: func(cmd *cobra.Command, args []string) (err error) { + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel mirror (sub)command failed") + }() + err = viper.MergeConfig(bytes.NewBuffer(defaultConfig)) + if err != nil { + return fmt.Errorf("unable to read default config: %w", err) + } for _, file := range *configFiles { viper.SetConfigFile(file) err := viper.MergeInConfig() - logging.WithFields("file", file).OnError(err).Warn("unable to read config file") + logging.OnError(cmd.Context(), err).Error("unable to read config file") } + return nil }, RunE: func(cmd *cobra.Command, args []string) (err error) { defer func() { - if err != nil { - slog.Error("zitadel mirror command failed", "err", err) - } + logging.OnError(cmd.Context(), err).Error("zitadel mirror command failed") }() - config, shutdown, err := mustNewMigrationConfig(cmd.Context(), viper.GetViper()) + config, shutdown, err := newMigrationConfig(cmd, viper.GetViper()) if err != nil { return fmt.Errorf("unable to create migration config: %w", err) } @@ -62,7 +65,10 @@ Order of execution: err = errors.Join(err, shutdown(cmd.Context())) }() - projectionConfig := mustNewProjectionsConfig(viper.GetViper()) + projectionConfig, _, err := newProjectionsConfig(cmd, viper.GetViper()) + if err != nil { + return fmt.Errorf("unable to create projections config: %w", err) + } masterKey, err := key.MasterKey(cmd) if err != nil { @@ -72,7 +78,6 @@ Order of execution: copySystem(cmd.Context(), config) copyAuth(cmd.Context(), config) copyEventstore(cmd.Context(), config) - projections(cmd.Context(), projectionConfig, masterKey) return nil }, diff --git a/cmd/mirror/projections.go b/cmd/mirror/projections.go index 5a2b8cda8..9b9ae9a4a 100644 --- a/cmd/mirror/projections.go +++ b/cmd/mirror/projections.go @@ -3,6 +3,7 @@ package mirror import ( "context" "database/sql" + "errors" "fmt" "net/http" "sync" @@ -10,8 +11,10 @@ import ( "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + old_logging "github.com/zitadel/logging" //nolint:staticcheck + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/encryption" "github.com/zitadel/zitadel/cmd/key" "github.com/zitadel/zitadel/cmd/tls" @@ -51,13 +54,24 @@ func projectionsCmd() *cobra.Command { cmd := &cobra.Command{ Use: "projections", Short: "calls the projections synchronously", - Run: func(cmd *cobra.Command, args []string) { - config := mustNewProjectionsConfig(viper.GetViper()) + RunE: func(cmd *cobra.Command, args []string) (err error) { + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel mirror projections command failed") + }() + config, shutdown, err := newProjectionsConfig(cmd, viper.GetViper()) + if err != nil { + return fmt.Errorf("unable to create projections config: %w", err) + } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) + }() masterKey, err := key.MasterKey(cmd) - logging.OnError(err).Fatal("unable to read master key") - + if err != nil { + return fmt.Errorf("unable to read master key: %w", err) + } projections(cmd.Context(), config, masterKey) + return nil }, } @@ -67,18 +81,19 @@ func projectionsCmd() *cobra.Command { } type ProjectionsConfig struct { - Destination database.Config - Projections projection.Config - Notifications handlers.WorkerConfig - EncryptionKeys *encryption.EncryptionKeyConfig - SystemAPIUsers map[string]*internal_authz.SystemAPIUser - Eventstore *eventstore.Config - Caches *connector.CachesConfig + Instrumentation instrumentation.Config + Destination database.Config + Projections projection.Config + Notifications handlers.WorkerConfig + EncryptionKeys *encryption.EncryptionKeyConfig + SystemAPIUsers map[string]*internal_authz.SystemAPIUser + Eventstore *eventstore.Config + Caches *connector.CachesConfig Admin admin_es.Config Auth auth_es.Config - Log *logging.Config + Log *old_logging.Config Machine *id.Config ExternalPort uint16 @@ -104,21 +119,21 @@ func projections( ctx context.Context, config *ProjectionsConfig, masterKey string, -) { - logging.Info("starting to fill projections") +) error { + logging.Info(ctx, "starting to fill projections") start := time.Now() client, err := database.Connect(config.Destination, false) - logging.OnError(err).Fatal("unable to connect to database") + logging.OnError(ctx, err).Fatal("unable to connect to database") keyStorage, err := crypto_db.NewKeyStorage(client, masterKey) - logging.OnError(err).Fatal("cannot start key storage") + logging.OnError(ctx, err).Fatal("cannot start key storage") keys, err := encryption.EnsureEncryptionKeys(ctx, config.EncryptionKeys, keyStorage) - logging.OnError(err).Fatal("unable to read encryption keys") + logging.OnError(ctx, err).Fatal("unable to read encryption keys") staticStorage, err := config.AssetStorage.NewStorage(client.DB) - logging.OnError(err).Fatal("unable create static storage") + logging.OnError(ctx, err).Fatal("unable create static storage") newEventstore := new_es.NewEventstore(client) config.Eventstore.Querier = old_es.NewPostgres(client) @@ -133,7 +148,7 @@ func projections( sessionTokenVerifier := internal_authz.SessionTokenVerifier(keys.OIDC) cacheConnectors, err := connector.StartConnectors(config.Caches, client) - logging.OnError(err).Fatal("unable to start caches") + logging.OnError(ctx, err).Fatal("unable to start caches") queries, err := query.StartQueries( ctx, @@ -162,10 +177,10 @@ func projections( config.SystemAPIUsers, false, ) - logging.OnError(err).Fatal("unable to start queries") + logging.OnError(ctx, err).Fatal("unable to start queries") authZRepo, err := authz.Start(queries, es, client, keys.OIDC, config.ExternalSecure) - logging.OnError(err).Fatal("unable to start authz repo") + logging.OnError(ctx, err).Fatal("unable to start authz repo") webAuthNConfig := &webauthn.Config{ DisplayName: config.WebAuthNName, @@ -202,10 +217,10 @@ func projections( nil, nil, ) - logging.OnError(err).Fatal("unable to start commands") + logging.OnError(ctx, err).Fatal("unable to start commands") err = projection.Create(ctx, client, es, config.Projections, keys.OIDC, keys.SAML, config.SystemAPIUsers) - logging.OnError(err).Fatal("unable to start projections") + logging.OnError(ctx, err).Fatal("unable to start projections") i18n.MustLoadSupportedLanguagesFromDir() @@ -235,13 +250,13 @@ func projections( config.Auth.Spooler.Client = client config.Auth.Spooler.Eventstore = es authView, err := auth_view.StartView(config.Auth.Spooler.Client, keys.OIDC, queries, config.Auth.Spooler.Eventstore) - logging.OnError(err).Fatal("unable to start auth view") + logging.OnError(ctx, err).Fatal("unable to start auth view") auth_handler.Register(ctx, config.Auth.Spooler, authView, queries) config.Admin.Spooler.Client = client config.Admin.Spooler.Eventstore = es adminView, err := admin_view.StartView(config.Admin.Spooler.Client) - logging.OnError(err).Fatal("unable to start admin view") + logging.OnError(ctx, err).Fatal("unable to start admin view") admin_handler.Register(ctx, config.Admin.Spooler, adminView, staticStorage) @@ -252,7 +267,7 @@ func projections( go func() { for instance := range failedInstances { - logging.WithFields("instance", instance).Error("projection failed") + logging.WithError(ctx, errors.New("projection failed for instance")).Error("projection failed", "instance", instance) } }() @@ -263,64 +278,65 @@ func projections( existingInstances := queryInstanceIDs(ctx, client) for i, instance := range existingInstances { instances <- instance - logging.WithFields("id", instance, "index", fmt.Sprintf("%d/%d", i, len(existingInstances))).Info("instance queued for projection") + logging.Info(ctx, "instance queued for projection", "instance", instance, "index", fmt.Sprintf("%d/%d", i, len(existingInstances))) } close(instances) wg.Wait() close(failedInstances) - logging.WithFields("took", time.Since(start)).Info("projections executed") + logging.Info(ctx, "projections executed", "took", time.Since(start)) + return nil } func execProjections(ctx context.Context, instances <-chan string, failedInstances chan<- string, wg *sync.WaitGroup) { for instance := range instances { - logging.WithFields("instance", instance).Info("starting projections") ctx = internal_authz.WithInstanceID(ctx, instance) + logging.Info(ctx, "starting projections") err := projection.ProjectInstance(ctx) if err != nil { - logging.WithFields("instance", instance).WithError(err).Info("trigger failed") + logging.WithError(ctx, err).Error("trigger failed") failedInstances <- instance continue } err = projection.ProjectInstanceFields(ctx) if err != nil { - logging.WithFields("instance", instance).WithError(err).Info("trigger fields failed") + logging.WithError(ctx, err).Error("trigger fields failed") failedInstances <- instance continue } err = admin_handler.ProjectInstance(ctx) if err != nil { - logging.WithFields("instance", instance).WithError(err).Info("trigger admin handler failed") + logging.WithError(ctx, err).Error("trigger admin handler failed") failedInstances <- instance continue } err = projection.ProjectInstanceFields(ctx) if err != nil { - logging.WithFields("instance", instance).WithError(err).Info("trigger fields failed") + logging.WithError(ctx, err).Error("trigger fields failed") failedInstances <- instance continue } err = auth_handler.ProjectInstance(ctx) if err != nil { - logging.WithFields("instance", instance).WithError(err).Info("trigger auth handler failed") + logging.WithError(ctx, err).Error("trigger auth handler failed") failedInstances <- instance continue } err = notification.ProjectInstance(ctx) if err != nil { - logging.WithFields("instance", instance).WithError(err).Info("trigger notification failed") + logging.WithError(ctx, err).Error("trigger notification failed") failedInstances <- instance continue } - logging.WithFields("instance", instance).Info("projections done") + logging.Info(ctx, "projections done") } wg.Done() } @@ -348,7 +364,6 @@ func queryInstanceIDs(ctx context.Context, source *database.DB) []string { }, "SELECT DISTINCT instance_id FROM eventstore.events2 WHERE instance_id <> '' AND aggregate_type = 'instance' AND event_type = 'instance.added' AND instance_id NOT IN (SELECT instance_id FROM eventstore.events2 WHERE instance_id <> '' AND aggregate_type = 'instance' AND event_type = 'instance.removed')", ) - logging.OnError(err).Fatal("unable to query instances") - + logging.OnError(ctx, err).Fatal("unable to query instances") return instances } diff --git a/cmd/mirror/system.go b/cmd/mirror/system.go index cb11eda47..32528d77a 100644 --- a/cmd/mirror/system.go +++ b/cmd/mirror/system.go @@ -10,8 +10,8 @@ import ( "github.com/jackc/pgx/v5/stdlib" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -23,7 +23,10 @@ func systemCmd() *cobra.Command { ZITADEL needs to be initialized Only keys and assets are mirrored`, RunE: func(cmd *cobra.Command, args []string) (err error) { - config, shutdown, err := mustNewMigrationConfig(cmd.Context(), viper.GetViper()) + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel mirror system command failed") + }() + config, shutdown, err := newMigrationConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -42,11 +45,11 @@ Only keys and assets are mirrored`, func copySystem(ctx context.Context, config *Migration) { sourceClient, err := database.Connect(config.Source, false) - logging.OnError(err).Fatal("unable to connect to source database") + logging.OnError(ctx, err).Fatal("unable to connect to source database") defer sourceClient.Close() destClient, err := database.Connect(config.Destination, false) - logging.OnError(err).Fatal("unable to connect to destination database") + logging.OnError(ctx, err).Fatal("unable to connect to destination database") defer destClient.Close() copyAssets(ctx, sourceClient, destClient) @@ -54,11 +57,11 @@ func copySystem(ctx context.Context, config *Migration) { } func copyAssets(ctx context.Context, source, dest *database.DB) { - logging.Info("starting to copy assets") + logging.Info(ctx, "starting to copy assets") start := time.Now() sourceConn, err := source.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire source connection") + logging.OnError(ctx, err).Fatal("unable to acquire source connection") defer sourceConn.Close() r, w := io.Pipe() @@ -76,7 +79,7 @@ func copyAssets(ctx context.Context, source, dest *database.DB) { }() destConn, err := dest.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire dest connection") + logging.OnError(ctx, err).Fatal("unable to acquire dest connection") defer destConn.Close() var assetCount int64 @@ -95,17 +98,17 @@ func copyAssets(ctx context.Context, source, dest *database.DB) { return err }) - logging.OnError(err).Fatal("unable to copy assets to destination") - logging.OnError(<-errs).Fatal("unable to copy assets from source") - logging.WithFields("took", time.Since(start), "count", assetCount).Info("assets migrated") + logging.OnError(ctx, err).Fatal("unable to copy assets to destination") + logging.OnError(ctx, <-errs).Fatal("unable to copy assets from source") + logging.Info(ctx, "assets migrated", "took", time.Since(start), "count", assetCount) } func copyEncryptionKeys(ctx context.Context, source, dest *database.DB) { - logging.Info("starting to copy encryption keys") + logging.Info(ctx, "starting to copy encryption keys") start := time.Now() sourceConn, err := source.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire source connection") + logging.OnError(ctx, err).Fatal("unable to acquire source connection") defer sourceConn.Close() r, w := io.Pipe() @@ -123,7 +126,7 @@ func copyEncryptionKeys(ctx context.Context, source, dest *database.DB) { }() destConn, err := dest.Conn(ctx) - logging.OnError(err).Fatal("unable to acquire dest connection") + logging.OnError(ctx, err).Fatal("unable to acquire dest connection") defer destConn.Close() var keyCount int64 @@ -142,7 +145,7 @@ func copyEncryptionKeys(ctx context.Context, source, dest *database.DB) { return err }) - logging.OnError(err).Fatal("unable to copy encryption keys to destination") - logging.OnError(<-errs).Fatal("unable to copy encryption keys from source") - logging.WithFields("took", time.Since(start), "count", keyCount).Info("encryption keys migrated") + logging.OnError(ctx, err).Fatal("unable to copy encryption keys to destination") + logging.OnError(ctx, <-errs).Fatal("unable to copy encryption keys from source") + logging.Info(ctx, "encryption keys migrated", "took", time.Since(start), "count", keyCount) } diff --git a/cmd/mirror/verify.go b/cmd/mirror/verify.go index ba2e3d30d..2d5009042 100644 --- a/cmd/mirror/verify.go +++ b/cmd/mirror/verify.go @@ -10,8 +10,8 @@ import ( "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" cryptoDatabase "github.com/zitadel/zitadel/internal/crypto/database" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/query/projection" @@ -22,7 +22,10 @@ func verifyCmd() *cobra.Command { Use: "verify", Short: "counts if source and dest have the same amount of entries", RunE: func(cmd *cobra.Command, args []string) (err error) { - config, shutdown, err := mustNewMigrationConfig(cmd.Context(), viper.GetViper()) + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel mirror verify command failed") + }() + config, shutdown, err := newMigrationConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -45,11 +48,11 @@ var schemas = []string{ func verifyMigration(ctx context.Context, config *Migration) { sourceClient, err := database.Connect(config.Source, false) - logging.OnError(err).Fatal("unable to connect to source database") + logging.OnError(ctx, err).Fatal("unable to connect to source database") defer sourceClient.Close() destClient, err := database.Connect(config.Destination, false) - logging.OnError(err).Fatal("unable to connect to destination database") + logging.OnError(ctx, err).Fatal("unable to connect to destination database") defer destClient.Close() for _, schema := range schemas { @@ -57,12 +60,12 @@ func verifyMigration(ctx context.Context, config *Migration) { sourceCount := countEntries(ctx, sourceClient, table) destCount := countEntries(ctx, destClient, table) - entry := logging.WithFields("table", table, "dest", destCount, "source", sourceCount) + logger := logging.FromCtx(ctx).With("table", table, "dest", destCount, "source", sourceCount) if sourceCount == destCount { - entry.Debug("equal count") + logger.DebugContext(ctx, "equal count") continue } - entry.WithField("diff", destCount-sourceCount).Info("unequal count") + logger.InfoContext(ctx, "unequal count", "diff", destCount-sourceCount) } } } @@ -83,7 +86,7 @@ func getTables(ctx context.Context, dest *database.DB, schema string) (tables [] "SELECT CONCAT(schemaname, '.', tablename) FROM pg_tables WHERE schemaname = $1", schema, ) - logging.WithFields("schema", schema).OnError(err).Fatal("unable to query tables") + logging.OnError(ctx, err).Fatal("unable to query tables") return tables } @@ -103,7 +106,7 @@ func getViews(ctx context.Context, dest *database.DB, schema string) (tables []s "SELECT CONCAT(schemaname, '.', viewname) FROM pg_views WHERE schemaname = $1", schema, ) - logging.WithFields("schema", schema).OnError(err).Fatal("unable to query views") + logging.OnError(ctx, err).Fatal("unable to query views") return tables } @@ -125,7 +128,7 @@ func countEntries(ctx context.Context, client *database.DB, table string) (count }, fmt.Sprintf("SELECT COUNT(*) FROM %s %s", table, instanceClause), ) - logging.WithFields("table", table, "db", client.DatabaseName()).OnError(err).Error("unable to count") + logging.OnError(ctx, err).Fatal("unable to count") return count } diff --git a/cmd/ready/config.go b/cmd/ready/config.go index f5067c562..82f5d0738 100644 --- a/cmd/ready/config.go +++ b/cmd/ready/config.go @@ -1,24 +1,29 @@ package ready import ( + "fmt" "time" "github.com/mitchellh/mapstructure" + "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + old_logging "github.com/zitadel/logging" //nolint:staticcheck + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" internal_authz "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/config/hook" "github.com/zitadel/zitadel/internal/config/network" ) type Config struct { - Log *logging.Config - Port uint16 - TLS network.TLS + Instrumentation instrumentation.Config + Log *old_logging.Config + Port uint16 + TLS network.TLS } -func MustNewConfig(v *viper.Viper) *Config { +func newConfig(cmd *cobra.Command, v *viper.Viper) (*Config, instrumentation.ShutdownFunc, error) { config := new(Config) err := v.Unmarshal(config, viper.DecodeHook(mapstructure.ComposeDecodeHookFunc( @@ -30,10 +35,23 @@ func MustNewConfig(v *viper.Viper) *Config { mapstructure.TextUnmarshallerHookFunc(), )), ) - logging.OnError(err).Fatal("unable to read default config") - + if err != nil { + return nil, nil, fmt.Errorf("unable to read default config: %w", err) + } + // Force-disable metrics and tracing for ready command + config.Instrumentation.Metric.Exporter.Type = instrumentation.ExporterTypeNone + config.Instrumentation.Trace.Exporter.Type = instrumentation.ExporterTypeNone + // Legacy logger err = config.Log.SetLogger() - logging.OnError(err).Fatal("unable to set logger") + if err != nil { + return nil, nil, fmt.Errorf("unable to set logger: %w", err) + } - return config + shutdown, err := instrumentation.Start(cmd.Context(), config.Instrumentation) + if err != nil { + return nil, nil, fmt.Errorf("unable to start instrumentation: %w", err) + } + cmd.SetContext(logging.NewCtx(cmd.Context(), logging.StreamRuntime)) + + return config, shutdown, nil } diff --git a/cmd/ready/ready.go b/cmd/ready/ready.go index 2b96db650..ed60f3b02 100644 --- a/cmd/ready/ready.go +++ b/cmd/ready/ready.go @@ -1,15 +1,17 @@ package ready import ( + "context" "crypto/tls" + "errors" "net" "net/http" - "os" "strconv" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" ) func New() *cobra.Command { @@ -17,16 +19,28 @@ func New() *cobra.Command { Use: "ready", Short: "Checks if zitadel is ready", Long: "Checks if zitadel is ready", - Run: func(cmd *cobra.Command, args []string) { - config := MustNewConfig(viper.GetViper()) - if !ready(config) { - os.Exit(1) + RunE: func(cmd *cobra.Command, args []string) (err error) { + // Overwrite context with ready stream for logging + cmd.SetContext(logging.NewCtx(cmd.Context(), logging.StreamReady)) + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel ready command failed") + }() + config, shutdown, err := newConfig(cmd, viper.GetViper()) + if err != nil { + return err } + defer func() { + err = errors.Join(err, shutdown(cmd.Context())) + }() + if ready(cmd.Context(), config) { + return nil + } + return errors.New("not ready") }, } } -func ready(config *Config) bool { +func ready(ctx context.Context, config *Config) bool { scheme := "https" if !config.TLS.Enabled { scheme = "http" @@ -35,12 +49,12 @@ func ready(config *Config) bool { httpClient := http.Client{Transport: &http.Transport{TLSClientConfig: &tls.Config{InsecureSkipVerify: true}}} res, err := httpClient.Get(scheme + "://" + net.JoinHostPort("localhost", strconv.Itoa(int(config.Port))) + "/debug/ready") if err != nil { - logging.WithError(err).Warn("ready check failed") + logging.WithError(ctx, err).Warn("get request failed") return false } defer res.Body.Close() if res.StatusCode != 200 { - logging.WithFields("status", res.StatusCode).Warn("ready check failed") + logging.Warn(ctx, "get request failed", "status", res.StatusCode) return false } return true diff --git a/cmd/setup/10.go b/cmd/setup/10.go index b134fcab6..e9397b74c 100644 --- a/cmd/setup/10.go +++ b/cmd/setup/10.go @@ -7,8 +7,8 @@ import ( "time" "github.com/cockroachdb/cockroach-go/v2/crdb" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -36,38 +36,39 @@ func (mig *CorrectCreationDate) Execute(ctx context.Context, _ eventstore.Event) defer cancel() for i := 0; ; i++ { - logging.WithFields("mig", mig.String(), "iteration", i).Debug("start iteration") + logCtx := logging.With(ctx, "mig", mig.String(), "iteration", i) + logging.Info(logCtx, "start iteration") var affected int64 - err = crdb.ExecuteTx(ctx, mig.dbClient.DB, nil, func(tx *sql.Tx) error { - _, err := tx.ExecContext(ctx, correctCreationDate10CreateTable) + err = crdb.ExecuteTx(logCtx, mig.dbClient.DB, nil, func(tx *sql.Tx) error { + _, err := tx.ExecContext(logCtx, correctCreationDate10CreateTable) if err != nil { return err } - logging.WithFields("mig", mig.String(), "iteration", i).Debug("temp table created") + logging.Debug(logCtx, "temp table created") - _, err = tx.ExecContext(ctx, correctCreationDate10Truncate) + _, err = tx.ExecContext(logCtx, correctCreationDate10Truncate) if err != nil { return err } - _, err = tx.ExecContext(ctx, correctCreationDate10FillTable) + _, err = tx.ExecContext(logCtx, correctCreationDate10FillTable) if err != nil { return err } - logging.WithFields("mig", mig.String(), "iteration", i).Debug("temp table filled") + logging.Debug(logCtx, "temp table filled") - res := tx.QueryRowContext(ctx, correctCreationDate10CountWrongEvents) + res := tx.QueryRowContext(logCtx, correctCreationDate10CountWrongEvents) if err := res.Scan(&affected); err != nil || affected == 0 { return err } - _, err = tx.ExecContext(ctx, correctCreationDate10Update) + _, err = tx.ExecContext(logCtx, correctCreationDate10Update) if err != nil { return err } - logging.WithFields("mig", mig.String(), "iteration", i, "count", affected).Debug("creation dates updated") + logging.Debug(logCtx, "creation dates updated") return nil }) - logging.WithFields("mig", mig.String(), "iteration", i).Debug("end iteration") + logging.Debug(logCtx, "end iteration") if affected == 0 || err != nil { return err } diff --git a/cmd/setup/14.go b/cmd/setup/14.go index 2cd5ac2c5..5f747e4a7 100644 --- a/cmd/setup/14.go +++ b/cmd/setup/14.go @@ -8,8 +8,8 @@ import ( "strings" "github.com/jackc/pgx/v5/pgconn" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -45,7 +45,7 @@ func (mig *NewEventsTable) Execute(ctx context.Context, _ eventstore.Event) erro } for _, stmt := range statements { stmt.query = strings.ReplaceAll(stmt.query, "{{.username}}", mig.dbClient.Username()) - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) _, err = mig.dbClient.ExecContext(ctx, stmt.query) if err != nil { return err diff --git a/cmd/setup/15.go b/cmd/setup/15.go index 54161ddef..0ff9fb639 100644 --- a/cmd/setup/15.go +++ b/cmd/setup/15.go @@ -4,8 +4,7 @@ import ( "context" "embed" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -25,7 +24,7 @@ func (mig *CurrentProjectionState) Execute(ctx context.Context, _ eventstore.Eve return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) _, err = mig.dbClient.ExecContext(ctx, stmt.query) if err != nil { return err diff --git a/cmd/setup/16.go b/cmd/setup/16.go index d6ad17091..8580fb4fe 100644 --- a/cmd/setup/16.go +++ b/cmd/setup/16.go @@ -4,8 +4,7 @@ import ( "context" _ "embed" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -25,7 +24,7 @@ func (mig *UniqueConstraintToLower) Execute(ctx context.Context, _ eventstore.Ev return err } count, err := res.RowsAffected() - logging.WithFields("count", count).Info("unique constraints updated") + logging.Info(ctx, "unique constraints updated", "count", count) return err } diff --git a/cmd/setup/35.go b/cmd/setup/35.go index 68e08bdfd..5e02e60b7 100644 --- a/cmd/setup/35.go +++ b/cmd/setup/35.go @@ -5,8 +5,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -26,7 +25,7 @@ func (mig *AddPositionToIndexEsWm) Execute(ctx context.Context, _ eventstore.Eve return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.dbClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/36.go b/cmd/setup/36.go index 7536c584b..19083c6b9 100644 --- a/cmd/setup/36.go +++ b/cmd/setup/36.go @@ -10,8 +10,8 @@ import ( "github.com/jackc/pgx/v5" "github.com/jackc/pgx/v5/pgconn" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/command" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" @@ -82,19 +82,20 @@ func (mig *FillV3Milestones) pushEventsByInstance(ctx context.Context, milestone slices.Sort(order) for i, instanceID := range order { - logging.WithFields("instance_id", instanceID, "migration", mig.String(), "progress", fmt.Sprintf("%d/%d", i+1, len(order))).Info("filter existing milestone events") + logCtx := logging.With(ctx, "instance", instanceID, "migration", mig.String()) + logging.Info(logCtx, "filter existing milestone events", "progress", fmt.Sprintf("%d/%d", i+1, len(order))) // because each Push runs in a separate TX, we need to make sure that events // from a partially executed migration are pushed again. model := command.NewMilestonesReachedWriteModel(instanceID) - if err := mig.eventstore.FilterToQueryReducer(ctx, model); err != nil { + if err := mig.eventstore.FilterToQueryReducer(logCtx, model); err != nil { return fmt.Errorf("milestones filter: %w", err) } if model.InstanceCreated { - logging.WithFields("instance_id", instanceID, "migration", mig.String()).Info("milestone events already migrated") + logging.Info(logCtx, "milestone events already migrated") continue // This instance was migrated, skip } - logging.WithFields("instance_id", instanceID, "migration", mig.String()).Info("push milestone events") + logging.Info(logCtx, "push milestone events") aggregate := milestone.NewInstanceAggregate(instanceID) diff --git a/cmd/setup/39.go b/cmd/setup/39.go index 8d78299e9..8782bc0a9 100644 --- a/cmd/setup/39.go +++ b/cmd/setup/39.go @@ -5,8 +5,7 @@ import ( _ "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/repository/instance" ) @@ -34,7 +33,7 @@ func (mig *DeleteStaleOrgFields) Execute(ctx context.Context, _ eventstore.Event return err } for i, instance := range instances { - logging.WithFields("instance_id", instance, "migration", mig.String(), "progress", fmt.Sprintf("%d/%d", i+1, len(instances))).Info("execute delete query") + logging.Info(ctx, "execute delete query", "instance", instance, "migration", mig.String(), "progress", fmt.Sprintf("%d/%d", i+1, len(instances))) if _, err := mig.eventstore.Client().ExecContext(ctx, deleteStaleOrgFields, instance); err != nil { return err } diff --git a/cmd/setup/40.go b/cmd/setup/40.go index 86cdab0d1..1b9bb5dab 100644 --- a/cmd/setup/40.go +++ b/cmd/setup/40.go @@ -10,8 +10,7 @@ import ( "strings" "text/template" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -39,7 +38,7 @@ func (mig *InitPushFunc) Execute(ctx context.Context, _ eventstore.Event) (err e } defer func() { closeErr := conn.Close() - logging.OnError(closeErr).Debug("failed to release connection") + logging.OnError(ctx, closeErr).Debug("failed to release connection") // Force the pool to reopen connections to apply the new types mig.dbClient.Pool.Reset() }() @@ -48,7 +47,7 @@ func (mig *InitPushFunc) Execute(ctx context.Context, _ eventstore.Event) (err e return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := conn.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/43.go b/cmd/setup/43.go index 1fa09773b..0fcaf7b7d 100644 --- a/cmd/setup/43.go +++ b/cmd/setup/43.go @@ -5,8 +5,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -26,7 +25,7 @@ func (mig *CreateFieldsDomainIndex) Execute(ctx context.Context, _ eventstore.Ev return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.dbClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/44.go b/cmd/setup/44.go index 5eb2f8d5c..096e852f3 100644 --- a/cmd/setup/44.go +++ b/cmd/setup/44.go @@ -5,8 +5,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -26,7 +25,7 @@ func (mig *ReplaceCurrentSequencesIndex) Execute(ctx context.Context, _ eventsto return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.dbClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/45.go b/cmd/setup/45.go index d8318a6d5..6c4fc5d79 100644 --- a/cmd/setup/45.go +++ b/cmd/setup/45.go @@ -6,8 +6,7 @@ import ( "encoding/json" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/query/projection" @@ -42,7 +41,7 @@ func (mig *CorrectProjectOwners) Execute(ctx context.Context, _ eventstore.Event ctx = authz.SetCtxData(ctx, authz.CtxData{UserID: "SETUP"}) for i, instance := range instances { ctx = authz.WithInstanceID(ctx, instance) - logging.WithFields("instance_id", instance, "migration", mig.String(), "progress", fmt.Sprintf("%d/%d", i+1, len(instances))).Info("correct owners of projects") + logging.Info(ctx, "correct owners of projects", "instance", instance, "migration", mig.String(), "progress", fmt.Sprintf("%d/%d", i+1, len(instances))) didCorrect, err := mig.correctInstanceProjects(ctx, instance) if err != nil { return err @@ -51,7 +50,7 @@ func (mig *CorrectProjectOwners) Execute(ctx context.Context, _ eventstore.Event continue } _, err = projection.ProjectGrantProjection.Trigger(ctx) - logging.OnError(err).Debug("failed triggering project grant projection to update owners") + logging.OnError(ctx, err).Debug("failed triggering project grant projection to update owners") } return nil } diff --git a/cmd/setup/46.go b/cmd/setup/46.go index 3593a1b66..22893808a 100644 --- a/cmd/setup/46.go +++ b/cmd/setup/46.go @@ -5,8 +5,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -26,7 +25,7 @@ func (mig *InitPermissionFunctions) Execute(ctx context.Context, _ eventstore.Ev return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.eventstoreClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/49.go b/cmd/setup/49.go index 846558914..9a0bfd2c8 100644 --- a/cmd/setup/49.go +++ b/cmd/setup/49.go @@ -5,8 +5,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -26,7 +25,7 @@ func (mig *InitPermittedOrgsFunction) Execute(ctx context.Context, _ eventstore. return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.eventstoreClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/53.go b/cmd/setup/53.go index 952fc3791..16f9b101a 100644 --- a/cmd/setup/53.go +++ b/cmd/setup/53.go @@ -5,8 +5,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -24,7 +23,7 @@ func (mig *InitPermittedOrgsFunction53) Execute(ctx context.Context, _ eventstor return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.dbClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/58.go b/cmd/setup/58.go index c46b30f54..2f1a6c592 100644 --- a/cmd/setup/58.go +++ b/cmd/setup/58.go @@ -6,8 +6,7 @@ import ( "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" ) @@ -36,7 +35,7 @@ func (mig *ReplaceLoginNames3View) Execute(ctx context.Context, _ eventstore.Eve return err } for _, stmt := range statements { - logging.WithFields("file", stmt.file, "migration", mig.String()).Info("execute statement") + logging.Info(ctx, "execute statement", "file", stmt.file, "migration", mig.String()) if _, err := mig.dbClient.ExecContext(ctx, stmt.query); err != nil { return fmt.Errorf("%s %s: %w", mig.String(), stmt.file, err) } diff --git a/cmd/setup/59.go b/cmd/setup/59.go index 530937d1a..be35c8dfe 100644 --- a/cmd/setup/59.go +++ b/cmd/setup/59.go @@ -4,8 +4,7 @@ import ( "context" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/command" "github.com/zitadel/zitadel/internal/crypto" @@ -41,7 +40,7 @@ func (mig *SetupWebkeys) Execute(ctx context.Context, _ eventstore.Event) error for _, instance := range instances { ctx := authz.WithInstanceID(ctx, instance) - logging.Info("prepare initial webkeys for instance", "instance_id", instance, "migration", mig) + logging.Info(ctx, "prepare initial webkeys for instance", "instance", instance, "migration", mig) if err := mig.commands.GenerateInitialWebKeys(ctx, conf); err != nil { return fmt.Errorf("%s generate initial webkeys: %w", mig, err) } diff --git a/cmd/setup/cleanup.go b/cmd/setup/cleanup.go index 371d1d582..215f84318 100644 --- a/cmd/setup/cleanup.go +++ b/cmd/setup/cleanup.go @@ -3,11 +3,12 @@ package setup import ( "context" "errors" + "fmt" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" old_es "github.com/zitadel/zitadel/internal/eventstore/repository/sql" @@ -21,39 +22,48 @@ func NewCleanup() *cobra.Command { Short: "cleans up migration if they got stuck", Long: `cleans up migration if they got stuck`, RunE: func(cmd *cobra.Command, args []string) (err error) { - config, shutdown, err := NewConfig(cmd.Context(), viper.GetViper()) + defer func() { + logging.OnError(cmd.Context(), err).Error("zitadel setup cleanup command failed") + }() + config, shutdown, err := NewConfig(cmd, viper.GetViper()) if err != nil { return err } defer func() { err = errors.Join(err, shutdown(cmd.Context())) }() - Cleanup(cmd.Context(), config) - return nil + return Cleanup(cmd.Context(), config) }, } } -func Cleanup(ctx context.Context, config *Config) { - logging.Info("cleanup started") +func Cleanup(ctx context.Context, config *Config) error { + logging.Info(ctx, "cleanup started") dbClient, err := database.Connect(config.Database, false) - logging.OnError(err).Fatal("unable to connect to database") + if err != nil { + return fmt.Errorf("unable to connect to database: %w", err) + } config.Eventstore.Pusher = new_es.NewEventstore(dbClient) config.Eventstore.Querier = old_es.NewPostgres(dbClient) es := eventstore.NewEventstore(config.Eventstore) step, err := migration.LastStuckStep(ctx, es) - logging.OnError(err).Fatal("unable to query latest migration") - - if step == nil { - logging.Info("there is no stuck migration please run `zitadel setup`") - return + if err != nil { + return fmt.Errorf("unable to query latest migration: %w", err) } - logging.WithFields("name", step.Name).Info("cleanup migration") + if step == nil { + logging.Info(ctx, "there is no stuck migration please run `zitadel setup`") + return nil + } + + logging.Info(ctx, "cleanup migration", "name", step.Name) err = migration.CancelStep(ctx, es, step) - logging.OnError(err).Fatal("cleanup migration failed please retry") + if err != nil { + return fmt.Errorf("cleanup migration failed please retry: %w", err) + } + return nil } diff --git a/cmd/setup/config.go b/cmd/setup/config.go index 2c1fcdbdf..b2d1ba71b 100644 --- a/cmd/setup/config.go +++ b/cmd/setup/config.go @@ -9,10 +9,12 @@ import ( "time" "github.com/mitchellh/mapstructure" + "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + old_logging "github.com/zitadel/logging" //nolint:staticcheck "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/encryption" "github.com/zitadel/zitadel/cmd/hooks" "github.com/zitadel/zitadel/internal/actions" @@ -44,7 +46,7 @@ type Config struct { ExternalPort uint16 ExternalSecure bool Instrumentation instrumentation.Config - Log *logging.Config + Log *old_logging.Config Metrics *instrumentation.LegacyMetricConfig EncryptionKeys *encryption.EncryptionKeyConfig DefaultInstance command.InstanceSetup @@ -70,7 +72,7 @@ type InitProjections struct { BulkLimit uint64 } -func NewConfig(ctx context.Context, v *viper.Viper) (*Config, instrumentation.ShutdownFunc, error) { +func NewConfig(cmd *cobra.Command, v *viper.Viper) (*Config, instrumentation.ShutdownFunc, error) { config := new(Config) err := v.Unmarshal(config, viper.DecodeHook(mapstructure.ComposeDecodeHookFunc( @@ -94,14 +96,16 @@ func NewConfig(ctx context.Context, v *viper.Viper) (*Config, instrumentation.Sh } config.Instrumentation.Metric.SetLegacyConfig(config.Metrics) - shutdown, err := instrumentation.Start(ctx, config.Instrumentation) + config.Instrumentation.Log.SetLegacyConfig(config.Log) + shutdown, err := instrumentation.Start(cmd.Context(), config.Instrumentation) if err != nil { return nil, nil, fmt.Errorf("unable to start instrumentation: %w", err) } + cmd.SetContext(logging.NewCtx(cmd.Context(), logging.StreamReady)) err = config.Log.SetLogger() if err != nil { - err = errors.Join(err, shutdown(ctx)) + err = errors.Join(err, shutdown(cmd.Context())) return nil, nil, fmt.Errorf("unable to set logger: %w", err) } @@ -180,18 +184,20 @@ type Steps struct { s69CacheTablesLogged *CacheTablesLogged } -func MustNewSteps(v *viper.Viper) *Steps { +func NewSteps(ctx context.Context, v *viper.Viper) (*Steps, error) { v.AutomaticEnv() v.SetEnvPrefix("ZITADEL") v.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) v.SetConfigType("yaml") err := v.ReadConfig(bytes.NewBuffer(defaultSteps)) - logging.OnError(err).Fatal("unable to read setup steps") + if err != nil { + return nil, fmt.Errorf("unable to read default steps: %w", err) + } for _, file := range stepFiles { v.SetConfigFile(file) err := v.MergeInConfig() - logging.WithFields("file", file).OnError(err).Warn("unable to read setup file") + logging.OnError(ctx, err).Warn("unable to read setup file", "file", file) } steps := new(Steps) @@ -205,6 +211,8 @@ func MustNewSteps(v *viper.Viper) *Steps { mapstructure.TextUnmarshallerHookFunc(), )), ) - logging.OnError(err).Fatal("unable to read steps") - return steps + if err != nil { + return nil, fmt.Errorf("unable to read steps: %w", err) + } + return steps, nil } diff --git a/cmd/setup/config_test.go b/cmd/setup/config_test.go index 6617cfcd2..faf5abafd 100644 --- a/cmd/setup/config_test.go +++ b/cmd/setup/config_test.go @@ -8,6 +8,7 @@ import ( "testing" "github.com/muhlemmer/gu" + "github.com/spf13/cobra" "github.com/spf13/viper" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -238,10 +239,13 @@ Actions: }} for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { + c := &cobra.Command{} + c.SetContext(t.Context()) + v := viper.New() v.SetConfigType("yaml") require.NoError(t, v.ReadConfig(strings.NewReader(tt.args.yaml))) - got, _, err := NewConfig(t.Context(), v) + got, _, err := NewConfig(c, v) require.NoError(t, err) tt.want(t, got) }) diff --git a/cmd/setup/setup.go b/cmd/setup/setup.go index 084145a09..c607923cf 100644 --- a/cmd/setup/setup.go +++ b/cmd/setup/setup.go @@ -6,7 +6,6 @@ import ( _ "embed" "errors" "fmt" - "log/slog" "net/http" "os" "os/signal" @@ -17,8 +16,8 @@ import ( "github.com/jackc/pgx/v5/pgconn" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/build" "github.com/zitadel/zitadel/cmd/encryption" "github.com/zitadel/zitadel/cmd/key" @@ -64,9 +63,7 @@ Requirements: - postgreSQL`, RunE: func(cmd *cobra.Command, args []string) (err error) { defer func() { - if err != nil { - slog.Error("zitadel setup command failed", "err", err) - } + logging.OnError(cmd.Context(), err).Error("zitadel setup command failed") }() err = tls.ModeFromFlag(cmd) @@ -84,7 +81,7 @@ Requirements: return fmt.Errorf("unable to bind \"for-mirror\" flag: %w", err) } - config, shutdown, err := NewConfig(cmd.Context(), viper.GetViper()) + config, shutdown, err := NewConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -92,15 +89,16 @@ Requirements: err = errors.Join(err, shutdown(cmd.Context())) }() - steps := MustNewSteps(viper.New()) + steps, err := NewSteps(cmd.Context(), viper.New()) + if err != nil { + return err + } masterKey, err := key.MasterKey(cmd) if err != nil { return fmt.Errorf("no master key provided: %w", err) } - - Setup(cmd.Context(), config, steps, masterKey) - return nil + return Setup(cmd.Context(), config, steps, masterKey) }, } @@ -127,9 +125,8 @@ func bindForMirror(cmd *cobra.Command) error { return viper.BindPFlag("ForMirror", cmd.Flags().Lookup("for-mirror")) } -func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) { - logging.Info("setup started") - +func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) (err error) { + logging.Info(ctx, "setup started") var setupErr error ctx, stop := signal.NotifyContext(ctx, os.Interrupt, syscall.SIGTERM) @@ -137,15 +134,14 @@ func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) stop() if setupErr == nil { - logging.Info("setup completed") + logging.Info(ctx, "setup completed") return } - if setupErr != nil && !errors.Is(setupErr, context.Canceled) { + if !errors.Is(setupErr, context.Canceled) { // If Setup failed for some other reason than the context being cancelled, // then this could be a fatal error we should not retry - logging.WithFields("error", setupErr).Fatal("setup failed, skipping cleanup") - return + logging.OnError(ctx, setupErr).Fatal("setup failed, skipping cleanup") } // if we're in the middle of long-running setup, run cleanup before exiting @@ -155,12 +151,13 @@ func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) cleanupCtx, cleanupCancel := context.WithTimeout(context.WithoutCancel(ctx), 10*time.Second) defer cleanupCancel() - Cleanup(cleanupCtx, config) + err = Cleanup(cleanupCtx, config) + logging.OnError(ctx, err).Error("setup cleanup failed") }() i18n.MustLoadSupportedLanguagesFromDir() dbClient, err := database.Connect(config.Database, false) - logging.OnError(err).Fatal("unable to connect to database") + logging.OnError(ctx, err).Fatal("unable to connect to database") config.Eventstore.Querier = old_es.NewPostgres(dbClient) esV3 := new_es.NewEventstore(dbClient) @@ -168,7 +165,7 @@ func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) config.Eventstore.Searcher = esV3 eventstoreClient := eventstore.NewEventstore(config.Eventstore) - logging.OnError(err).Fatal("unable to start eventstore") + logging.OnError(ctx, err).Fatal("unable to start eventstore") eventstoreV4 := es_v4.NewEventstoreFromOne(es_v4_pg.New(dbClient, &es_v4_pg.Config{ MaxRetries: config.Eventstore.MaxRetries, })) @@ -252,7 +249,9 @@ func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) steps.s69CacheTablesLogged = &CacheTablesLogged{dbClient: dbClient} err = projection.Create(ctx, dbClient, eventstoreClient, config.Projections, nil, nil, nil) - logging.OnError(err).Fatal("unable to start projections") + if err != nil { + return fmt.Errorf("unable to create projections: %w", err) + } for _, step := range []migration.Migration{ steps.s14NewEventsTable, @@ -383,6 +382,7 @@ func Setup(ctx context.Context, config *Config, steps *Steps, masterKey string) return } } + return nil } func executeMigration(ctx context.Context, eventstoreClient *eventstore.Eventstore, step migration.Migration, errorMsg string) error { @@ -403,8 +403,8 @@ func executeMigration(ctx context.Context, eventstoreClient *eventstore.Eventsto "hint", pgErr.Hint, ) } - logging.WithFields(logFields...).WithError(err).Error(errorMsg) - return fmt.Errorf("%s: %w", errorMsg, err) + logging.WithError(ctx, err).Error(errorMsg, logFields...) + return err } // readStmt reads a single file from the embedded FS, @@ -455,10 +455,10 @@ func startCommandsQueries( *auth_view.View, ) { keyStorage, err := cryptoDB.NewKeyStorage(dbClient, masterKey) - logging.OnError(err).Fatal("unable to start key storage") + logging.OnError(ctx, err).Fatal("unable to start key storage") keys, err := encryption.EnsureEncryptionKeys(ctx, config.EncryptionKeys, keyStorage) - logging.OnError(err).Fatal("unable to ensure encryption keys") + logging.OnError(ctx, err).Fatal("unable to ensure encryption keys") err = projection.Create( ctx, @@ -473,13 +473,13 @@ func startCommandsQueries( keys.SAML, config.SystemAPIUsers, ) - logging.OnError(err).Fatal("unable to start projections") + logging.OnError(ctx, err).Fatal("unable to start projections") staticStorage, err := config.AssetStorage.NewStorage(dbClient.DB) - logging.OnError(err).Fatal("unable to start asset storage") + logging.OnError(ctx, err).Fatal("unable to start asset storage") adminView, err := admin_view.StartView(dbClient) - logging.OnError(err).Fatal("unable to start admin view") + logging.OnError(ctx, err).Fatal("unable to start admin view") admin_handler.Register(ctx, admin_handler.Config{ Client: dbClient, @@ -494,7 +494,7 @@ func startCommandsQueries( sessionTokenVerifier := internal_authz.SessionTokenVerifier(keys.OIDC) cacheConnectors, err := connector.StartConnectors(config.Caches, dbClient) - logging.OnError(err).Fatal("unable to start caches") + logging.OnError(ctx, err).Fatal("unable to start caches") queries, err := query.StartQueries( ctx, @@ -523,10 +523,10 @@ func startCommandsQueries( nil, // not needed for projections false, ) - logging.OnError(err).Fatal("unable to start queries") + logging.OnError(ctx, err).Fatal("unable to start queries") authView, err := auth_view.StartView(dbClient, keys.OIDC, queries, eventstoreClient) - logging.OnError(err).Fatal("unable to start admin view") + logging.OnError(ctx, err).Fatal("unable to start auth view") auth_handler.Register(ctx, auth_handler.Config{ Client: dbClient, @@ -539,7 +539,7 @@ func startCommandsQueries( ) authZRepo, err := authz.Start(queries, eventstoreClient, dbClient, keys.OIDC, config.ExternalSecure) - logging.OnError(err).Fatal("unable to start authz repo") + logging.OnError(ctx, err).Fatal("unable to start authz repo") permissionCheck := func(ctx context.Context, permission, orgID, resourceID string) (err error) { return internal_authz.CheckPermission(ctx, authZRepo, config.SystemAuthZ.RolePermissionMappings, config.InternalAuthZ.RolePermissionMappings, permission, orgID, resourceID) } @@ -577,12 +577,12 @@ func startCommandsQueries( nil, nil, ) - logging.OnError(err).Fatal("unable to start commands") + logging.OnError(ctx, err).Fatal("unable to start commands") q, err := queue.NewQueue(&queue.Config{ Client: dbClient, }) - logging.OnError(err).Fatal("unable to init queue") + logging.OnError(ctx, err).Fatal("unable to init queue") notify_handler.Register( ctx, @@ -616,28 +616,28 @@ func initProjections( ) error { for _, p := range projection.Projections() { if err := migration.Migrate(ctx, eventstoreClient, p); err != nil { - logging.WithFields("name", p.String()).OnError(err).Error("projection migration failed") + logging.WithError(ctx, err).Error("projection migration failed", "name", p.String()) return err } } for _, p := range admin_handler.Projections() { if err := migration.Migrate(ctx, eventstoreClient, p); err != nil { - logging.WithFields("name", p.String()).OnError(err).Error("admin schema migration failed") + logging.WithError(ctx, err).Error("admin schema migration failed", "name", p.String()) return err } } for _, p := range auth_handler.Projections() { if err := migration.Migrate(ctx, eventstoreClient, p); err != nil { - logging.WithFields("name", p.String()).OnError(err).Error("auth schema migration failed") + logging.WithError(ctx, err).Error("auth schema migration failed", "name", p.String()) return err } } for _, p := range notify_handler.Projections() { if err := migration.Migrate(ctx, eventstoreClient, p); err != nil { - logging.WithFields("name", p.String()).OnError(err).Error("notification migration failed") + logging.WithError(ctx, err).Error("notification migration failed", "name", p.String()) return err } } diff --git a/cmd/setup/steps.yaml b/cmd/setup/steps.yaml index 8552b2fc0..7b2ab0344 100644 --- a/cmd/setup/steps.yaml +++ b/cmd/setup/steps.yaml @@ -12,11 +12,11 @@ Instrumentation: # "stdErr": Exports traces to standard error # "grpc": Exports traces using the OTEL gRPC exporter (recommended) # "http": Exports traces using the OTEL HTTP exporter - # "google": Exports traces to Google Cloud Trace + # "google": Exports traces to Google Cloud. Need to configure GoogleProjectID below! Type: "none" # ZITADEL_INSTRUMENTATION_TRACE_EXPORTER_TYPE # Endpoint of the OTEL collector for grpc and http exporters Endpoint: "" # ZITADEL_INSTRUMENTATION_TRACE_EXPORTER_ENDPOINT - # Disable https for grpc and http exporters + # Disable TLS for grpc and http exporters Insecure: false # ZITADEL_INSTRUMENTATION_TRACE_EXPORTER_INSECURE # Interval for batching traces before export BatchDuration: 1s # ZITADEL_INSTRUMENTATION_TRACE_EXPORTER_BATCHDURATION @@ -30,15 +30,15 @@ Instrumentation: # "stdErr": Exports metrics to standard error # "grpc": Exports metrics using the OTEL gRPC exporter (recommended) # "http": Exports metrics using the OTEL HTTP exporter - # "google": Exports metrics to Google Cloud Trace + # "google": Exports metrics to Google Cloud. Need to configure GoogleProjectID below! # "prometheus": Exposes metrics via an HTTP endpoint for Prometheus to scrape Type: "none" # ZITADEL_INSTRUMENTATION_METRIC_EXPORTER_TYPE # Endpoint of the OTEL collector for grpc and http exporters Endpoint: "" # ZITADEL_INSTRUMENTATION_METRIC_EXPORTER_ENDPOINT - # Disable https for grpc and http exporters + # Disable TLS for grpc and http exporters Insecure: false # ZITADEL_INSTRUMENTATION_METRIC_EXPORTER_INSECURE # Interval at which metrics are exported - BatchDuration: 1s # ZITADEL_INSTRUMENTATION_METRIC_EXPORTER_BATCHDURATION + BatchDuration: 1m # ZITADEL_INSTRUMENTATION_METRIC_EXPORTER_BATCHDURATION # Project ID for Google Cloud Trace exporter GoogleProjectID: "" # ZITADEL_INSTRUMENTATION_METRIC_EXPORTER_GOOGLEPROJECTID @@ -46,39 +46,67 @@ Instrumentation: Log: # Log lines lower than this level are not emitted. Level: "INFO" # ZITADEL_INSTRUMENTATION_LOG_LEVEL + # Streams enable logging for specific parts of the application. + Streams: # ZITADEL_INSTRUMENTATION_LOG_STREAMS (comma separated list) + - runtime # General runtime logs, such as startup and shutdown messages. + - request # Logs for incoming API and HTTP requests. + - event_handler # Logs for event handling in projections. + - queue # Logs for the job queue processing. + # - event_pusher # Logs for event pushing to the database. Warning: contains sensitive information. + # Mask replaces sensitive information with Value in logs matched by Key + Mask: + # Keys are the attribute keys to be masked in logs. + # Keys are unqualified attribute names and apply to all attributes with the specified name, + # regardless of their position in the attribute hierarchy. + # Eg. "some_key" matches "some_key" and "parent.some_key" etc. + # If the matched log attribute is a nested object or array, + # the entire structure is replaced with the specified Value. + Keys: # ZITADEL_INSTRUMENTATION_LOG_MASK_KEYS (comma separated list) + # - "first_name" + # - "last_name" + # Value is the string that replaces the original value of masked attributes. + Value: "****" # ZITADEL_INSTRUMENTATION_LOG_MASK_VALUE # Enable printing structured logs to standard error in the specified format. + # When disabled, the legacy Log configuration is used. + # Important: when legacy Log is customized, please add a format and customize before upgrading to v5 # The following formats are supported: - # - "disabled": Disables logging to standard error - # - "text": Logs are printed as human-readable text - # - "json": Logs are printed as JSON objects - # - "gcp": JSON formatted logs compatible with Google Cloud Platform logging - StdErr: "text" # ZITADEL_INSTRUMENTATION_LOG_STDERR + # - "disabled": Disables logging (or fallback to legacy Log config) + # - "text": Logs are printed on StdErr as human-readable text + # - "json": Logs are printed on StdErr as JSON objects + # - "gcp": JSON formatted logs compatible with Google Cloud Platform logging. + # - "gcp_error_reporting": JSON formatted logs compatible with Google Cloud Platform Error Reporting. + Format: "disabled" # ZITADEL_INSTRUMENTATION_LOG_STDERR # Adds the source file and line number where the log line was emitted. # Not to be confused with the source of an error. AddSource: true # ZITADEL_INSTRUMENTATION_LOG_ADDSOURCE + # Configure how errors are logged. + Errors: + # Adds the source file, line number and function where the error was created. + ReportLocation: true # ZITADEL_INSTRUMENTATION_LOG_ERRORS_REPORTLOCATION + # Adds stack traces to logged errors. + StackTrace: false # ZITADEL_INSTRUMENTATION_LOG_ERRORS_STACKTRACE Exporter: # The following exporter types are supported: - # - "none": Disables log exporting - # - "stdOut": Exports logs to standard output - # - "stdErr": Exports logs to standard error - # - "grpc": Exports logs using the OTEL gRPC exporter (recommended) - # - "http": Exports logs using the OTEL HTTP exporter + # - "none": Disables OTEL log exporter + # - "stdOut": Exports OTEL logs to standard output + # - "stdErr": Exports OTEL logs to standard error + # - "grpc": Exports OTEL logs using the OTEL gRPC exporter (recommended) + # - "http": Exports OTEL logs using the OTEL HTTP exporter Type: "none" # ZITADEL_INSTRUMENTATION_LOG_EXPORTER_TYPE # Endpoint of the OTEL collector for grpc and http exporters Endpoint: "" # ZITADEL_INSTRUMENTATION_LOG_EXPORTER_ENDPOINT - # Disable https for grpc and http exporters + # Disable TLS for grpc and http exporters Insecure: false # ZITADEL_INSTRUMENTATION_LOG_EXPORTER_INSECURE # Interval at which metrics are exported BatchDuration: 1s # ZITADEL_INSTRUMENTATION_LOG_EXPORTER_BATCHDURATION - # Project ID for Google Cloud Trace exporter - GoogleProjectID: "" # ZITADEL_INSTRUMENTATION_LOG_EXPORTER_GOOGLEPROJECTID Profile: - # The following profiler types are supported: - # "none": Disables profiling - # "google": Exports profiling data to Google Cloud Profiler - Type: "none" # ZITADEL_INSTRUMENTATION_PROFILE_TYPE - # Project ID for Google Cloud Profiler - GoogleProjectID: "" # ZITADEL_INSTRUMENTATION_PROFILE_GOOGLEPROJECTID + Exporter: + # The following profiler types are supported: + # "none": Disables profiling + # "google": Exports profiling data to Google Cloud Profiler + Type: "none" # ZITADEL_INSTRUMENTATION_PROFILE_TYPE + # Project ID for Google Cloud Profiler + GoogleProjectID: "" # ZITADEL_INSTRUMENTATION_PROFILE_GOOGLEPROJECTID # By using the FirstInstance section, you can overwrite the DefaultInstance configuration for the first instance created by zitadel setup. FirstInstance: diff --git a/cmd/setup/sync_role_permissions.go b/cmd/setup/sync_role_permissions.go index 5c380265b..ebc8db962 100644 --- a/cmd/setup/sync_role_permissions.go +++ b/cmd/setup/sync_role_permissions.go @@ -5,8 +5,7 @@ import ( _ "embed" "fmt" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/command" "github.com/zitadel/zitadel/internal/eventstore" @@ -23,6 +22,7 @@ type SyncRolePermissions struct { } func (mig *SyncRolePermissions) Execute(ctx context.Context, _ eventstore.Event) error { + ctx = logging.With(ctx, "migration", mig.String()) if err := mig.executeSystem(ctx); err != nil { return err } @@ -30,12 +30,12 @@ func (mig *SyncRolePermissions) Execute(ctx context.Context, _ eventstore.Event) } func (mig *SyncRolePermissions) executeSystem(ctx context.Context) error { - logging.WithFields("migration", mig.String()).Info("prepare system role permission sync events") + logging.Info(ctx, "prepare system role permission sync events") details, err := mig.commands.SynchronizeRolePermission(ctx, "SYSTEM", mig.rolePermissionMappings) if err != nil { return err } - logging.WithFields("migration", mig.String(), "sequence", details.Sequence).Info("pushed system role permission sync events") + logging.Info(ctx, "pushed system role permission sync events", "sequence", details.Sequence) return nil } @@ -57,12 +57,12 @@ func (mig *SyncRolePermissions) executeInstances(ctx context.Context) error { return err } for i, instanceID := range instances { - logging.WithFields("instance_id", instanceID, "migration", mig.String(), "progress", fmt.Sprintf("%d/%d", i+1, len(instances))).Info("prepare instance role permission sync events") + logging.Info(ctx, "prepare instance role permission sync events", "instance", instanceID, "progress", fmt.Sprintf("%d/%d", i+1, len(instances))) details, err := mig.commands.SynchronizeRolePermission(ctx, instanceID, mig.rolePermissionMappings) if err != nil { return err } - logging.WithFields("instance_id", instanceID, "migration", mig.String(), "sequence", details.Sequence).Info("pushed instance role permission sync events") + logging.Info(ctx, "pushed instance role permission sync events", "instance", instanceID, "sequence", details.Sequence) } return nil } diff --git a/cmd/start/config.go b/cmd/start/config.go index 414883e38..719961f11 100644 --- a/cmd/start/config.go +++ b/cmd/start/config.go @@ -1,16 +1,17 @@ package start import ( - "context" "errors" "fmt" "time" "github.com/mitchellh/mapstructure" + "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + old_logging "github.com/zitadel/logging" //nolint:staticcheck "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/encryption" "github.com/zitadel/zitadel/cmd/hooks" "github.com/zitadel/zitadel/internal/actions" @@ -42,7 +43,7 @@ import ( type Config struct { Instrumentation instrumentation.Config - Log *logging.Config + Log *old_logging.Config Port uint16 ExternalPort uint16 ExternalDomain string @@ -95,7 +96,7 @@ type QuotasConfig struct { Execution *logstore.EmitterConfig } -func NewConfig(ctx context.Context, v *viper.Viper) (*Config, instrumentation.ShutdownFunc, error) { +func NewConfig(cmd *cobra.Command, v *viper.Viper) (*Config, instrumentation.ShutdownFunc, error) { config, err := readConfig(v) if err != nil { return nil, nil, fmt.Errorf("unable to read config: %w", err) @@ -103,16 +104,18 @@ func NewConfig(ctx context.Context, v *viper.Viper) (*Config, instrumentation.Sh config.Instrumentation.Trace.SetLegacyConfig(config.Tracing) config.Instrumentation.Metric.SetLegacyConfig(config.Metrics) + config.Instrumentation.Log.SetLegacyConfig(config.Log) config.Instrumentation.Profile.SetLegacyConfig(config.Profiler) - shutdown, err := instrumentation.Start(ctx, config.Instrumentation) + shutdown, err := instrumentation.Start(cmd.Context(), config.Instrumentation) if err != nil { return nil, nil, fmt.Errorf("unable to start instrumentation: %w", err) } + cmd.SetContext(logging.NewCtx(cmd.Context(), logging.StreamRuntime)) // Legacy logger err = config.Log.SetLogger() if err != nil { - err = errors.Join(err, shutdown(ctx)) + err = errors.Join(err, shutdown(cmd.Context())) return nil, nil, fmt.Errorf("unable to set logger: %w", err) } @@ -123,7 +126,7 @@ func NewConfig(ctx context.Context, v *viper.Viper) (*Config, instrumentation.Sh err = config.SystemDefaults.Validate() if err != nil { - err = errors.Join(err, shutdown(ctx)) + err = errors.Join(err, shutdown(cmd.Context())) return nil, nil, fmt.Errorf("system defaults config invalid: %w", err) } // Copy the global role permissions mappings to the instance until we allow instance-level configuration over the API. diff --git a/cmd/start/flags.go b/cmd/start/flags.go index 7e7617712..93df21f73 100644 --- a/cmd/start/flags.go +++ b/cmd/start/flags.go @@ -4,8 +4,8 @@ import ( "github.com/spf13/cobra" "github.com/spf13/pflag" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/key" "github.com/zitadel/zitadel/cmd/tls" ) @@ -23,6 +23,7 @@ func init() { func startFlags(cmd *cobra.Command) { cmd.Flags().AddFlagSet(startFlagSet) logging.OnError( + cmd.Context(), viper.BindPFlags(startFlagSet), ).Fatal("start flags") diff --git a/cmd/start/start.go b/cmd/start/start.go index 6a0fa478c..9f5aea9f3 100644 --- a/cmd/start/start.go +++ b/cmd/start/start.go @@ -6,7 +6,6 @@ import ( _ "embed" "errors" "fmt" - "log/slog" "math" "net/http" "os" @@ -21,7 +20,6 @@ import ( "github.com/gorilla/mux" "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" "github.com/zitadel/oidc/v3/pkg/op" "github.com/zitadel/saml/pkg/provider" "golang.org/x/net/http2" @@ -29,6 +27,7 @@ import ( "golang.org/x/text/language" new_domain "github.com/zitadel/zitadel/backend/v3/domain" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" v3_postgres "github.com/zitadel/zitadel/backend/v3/storage/database/dialect/postgres" "github.com/zitadel/zitadel/cmd/build" "github.com/zitadel/zitadel/cmd/encryption" @@ -131,16 +130,14 @@ Requirements: - postgreSQL`, RunE: func(cmd *cobra.Command, args []string) (err error) { defer func() { - if err != nil { - slog.Error("zitadel start command failed", "err", err) - } + logging.OnError(cmd.Context(), err).Error("zitadel start command failed") }() err = cmd_tls.ModeFromFlag(cmd) if err != nil { return err } - config, shutdown, err := NewConfig(cmd.Context(), viper.GetViper()) + config, shutdown, err := NewConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -342,6 +339,7 @@ func startZitadel(ctx context.Context, config *Config, masterKey string, server notification.Start(ctx) execution.Register( + ctx, config.Executions, q, keys.Target, @@ -359,7 +357,7 @@ func startZitadel(ctx context.Context, config *Config, masterKey string, server } // the scheduler / periodic jobs need to be started after the queue already runs - if err = serviceping.Start(config.ServicePing, q); err != nil { + if err = serviceping.Start(ctx, config.ServicePing, q); err != nil { return err } @@ -750,7 +748,7 @@ func listen(ctx context.Context, router *mux.Router, port uint16, tlsConfig *tls errCh := make(chan error) go func() { - logging.Infof("server is listening on %s", lis.Addr().String()) + logging.Info(ctx, "server is listening", "address", lis.Addr().String()) if tlsConfig != nil { // we don't need to pass the files here, because we already initialized the TLS config on the server errCh <- http1Server.ServeTLS(lis, "", "") @@ -776,7 +774,7 @@ func shutdownServer(ctx context.Context, server *http.Server) error { if err != nil { return fmt.Errorf("could not shutdown gracefully: %w", err) } - logging.New().Info("server shutdown gracefully") + logging.Info(ctx, "server shutdown gracefully") return nil } diff --git a/cmd/start/start_from_init.go b/cmd/start/start_from_init.go index 4238141bf..4f96e2801 100644 --- a/cmd/start/start_from_init.go +++ b/cmd/start/start_from_init.go @@ -4,11 +4,11 @@ import ( "context" "errors" "fmt" - "log/slog" "github.com/spf13/cobra" "github.com/spf13/viper" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/initialise" "github.com/zitadel/zitadel/cmd/key" "github.com/zitadel/zitadel/cmd/setup" @@ -28,9 +28,7 @@ Requirements: - postgreSQL`, RunE: func(cmd *cobra.Command, args []string) (err error) { defer func() { - if err != nil { - slog.Error("zitadel start-from-init command failed", "err", err) - } + logging.OnError(cmd.Context(), err).Error("zitadel start-from-init command failed") }() err = tls.ModeFromFlag(cmd) @@ -43,30 +41,42 @@ Requirements: return fmt.Errorf("no master key provided: %w", err) } - initCtx, cancel := context.WithCancel(cmd.Context()) - initialise.InitAll(initCtx, initialise.MustNewConfig(viper.GetViper())) - cancel() - - err = setup.BindInitProjections(cmd) - if err != nil { - return fmt.Errorf("unable to bind \"init-projections\" flag: %w", err) - } - - setupConfig, shutdown, err := setup.NewConfig(cmd.Context(), viper.GetViper()) + initConfig, shutdown, err := initialise.NewConfig(cmd, viper.GetViper()) if err != nil { return err } defer func() { err = errors.Join(err, shutdown(cmd.Context())) }() + initCtx, cancel := context.WithCancel(cmd.Context()) + defer cancel() - setupSteps := setup.MustNewSteps(viper.New()) + err = initialise.InitAll(initCtx, initConfig) + if err != nil { + return err + } - setupCtx, cancel := context.WithCancel(cmd.Context()) - setup.Setup(setupCtx, setupConfig, setupSteps, masterKey) - cancel() + err = setup.BindInitProjections(cmd) + if err != nil { + return fmt.Errorf("unable to bind \"init-projections\" flag: %w", err) + } - startConfig, _, err := NewConfig(cmd.Context(), viper.GetViper()) + setupConfig, _, err := setup.NewConfig(cmd, viper.GetViper()) + if err != nil { + return err + } + + setupSteps, err := setup.NewSteps(cmd.Context(), viper.New()) + if err != nil { + return err + } + + err = setup.Setup(cmd.Context(), setupConfig, setupSteps, masterKey) + if err != nil { + return err + } + + startConfig, _, err := NewConfig(cmd, viper.GetViper()) if err != nil { return err } diff --git a/cmd/start/start_from_setup.go b/cmd/start/start_from_setup.go index 8d524664b..1460a4f11 100644 --- a/cmd/start/start_from_setup.go +++ b/cmd/start/start_from_setup.go @@ -1,13 +1,12 @@ package start import ( - "context" "errors" - "log/slog" "github.com/spf13/cobra" "github.com/spf13/viper" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/key" "github.com/zitadel/zitadel/cmd/setup" "github.com/zitadel/zitadel/cmd/tls" @@ -27,9 +26,7 @@ Requirements: `, RunE: func(cmd *cobra.Command, args []string) (err error) { defer func() { - if err != nil { - slog.Error("zitadel start-from-setup command failed", "err", err) - } + logging.OnError(cmd.Context(), err).Error("zitadel start-from-setup command failed") }() err = tls.ModeFromFlag(cmd) @@ -47,7 +44,7 @@ Requirements: return err } - setupConfig, shutdown, err := setup.NewConfig(cmd.Context(), viper.GetViper()) + setupConfig, shutdown, err := setup.NewConfig(cmd, viper.GetViper()) if err != nil { return err } @@ -55,13 +52,17 @@ Requirements: err = errors.Join(err, shutdown(cmd.Context())) }() - setupSteps := setup.MustNewSteps(viper.New()) + setupSteps, err := setup.NewSteps(cmd.Context(), viper.New()) + if err != nil { + return err + } - setupCtx, cancel := context.WithCancel(cmd.Context()) - setup.Setup(setupCtx, setupConfig, setupSteps, masterKey) - cancel() + err = setup.Setup(cmd.Context(), setupConfig, setupSteps, masterKey) + if err != nil { + return err + } - startConfig, _, err := NewConfig(cmd.Context(), viper.GetViper()) + startConfig, _, err := NewConfig(cmd, viper.GetViper()) if err != nil { return err } diff --git a/cmd/zitadel.go b/cmd/zitadel.go index 4cf22f9ce..c5d87ee45 100644 --- a/cmd/zitadel.go +++ b/cmd/zitadel.go @@ -2,6 +2,7 @@ package cmd import ( "bytes" + "context" _ "embed" "errors" "io" @@ -9,8 +10,8 @@ import ( "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd/admin" "github.com/zitadel/zitadel/cmd/build" "github.com/zitadel/zitadel/cmd/initialise" @@ -45,7 +46,7 @@ func New(out io.Writer, in io.Reader, args []string, server chan<- *start.Server viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) viper.SetConfigType("yaml") err := viper.ReadConfig(bytes.NewBuffer(defaultConfig)) - logging.OnError(err).Fatal("unable to read default config") + logging.OnError(context.Background(), err).Fatal("unable to read default config") cobra.OnInitialize(initConfig) cmd.PersistentFlags().StringArrayVar(&configFiles, "config", nil, "path to config file to overwrite system defaults") @@ -71,6 +72,6 @@ func initConfig() { for _, file := range configFiles { viper.SetConfigFile(file) err := viper.MergeInConfig() - logging.WithFields("file", file).OnError(err).Warn("unable to read config file") + logging.OnError(context.Background(), err).Warn("unable to read config file", "file", file) } } diff --git a/go.mod b/go.mod index 35a6d0f9d..913c0f0cf 100644 --- a/go.mod +++ b/go.mod @@ -84,7 +84,7 @@ require ( github.com/samber/slog-multi v1.6.0 github.com/santhosh-tekuri/jsonschema/v5 v5.3.1 github.com/shopspring/decimal v1.4.0 - github.com/sirupsen/logrus v1.9.3 + github.com/sirupsen/logrus v1.9.4 github.com/sony/gobreaker/v2 v2.3.0 github.com/sony/sonyflake v1.3.0 github.com/spf13/cobra v1.10.1 @@ -96,7 +96,7 @@ require ( github.com/veqryn/slog-context v0.8.0 github.com/veqryn/slog-context/otel v0.8.0 github.com/zitadel/exifremove v0.1.0 - github.com/zitadel/logging v0.6.2 + github.com/zitadel/logging v0.7.0 github.com/zitadel/oidc/v3 v3.45.0 github.com/zitadel/passwap v0.10.0 github.com/zitadel/saml v0.4.1 @@ -128,7 +128,7 @@ require ( golang.org/x/net v0.47.0 golang.org/x/oauth2 v0.33.0 golang.org/x/sync v0.18.0 - golang.org/x/sys v0.39.0 + golang.org/x/sys v0.40.0 golang.org/x/text v0.31.0 google.golang.org/api v0.256.0 google.golang.org/genproto/googleapis/api v0.0.0-20251202230838-ff82c1b0f217 diff --git a/go.sum b/go.sum index a24517371..b5f104951 100644 --- a/go.sum +++ b/go.sum @@ -734,8 +734,8 @@ github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPx github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88= github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= -github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ= -github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= +github.com/sirupsen/logrus v1.9.4 h1:TsZE7l11zFCLZnZ+teH4Umoq5BhEIfIzfRDZ1Uzql2w= +github.com/sirupsen/logrus v1.9.4/go.mod h1:ftWc9WdOfJ0a92nsE2jF5u5ZwH8Bv2zdeOC42RjbV2g= github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d h1:zE9ykElWQ6/NYmHa3jpm/yHnI4xSofP+UP6SpjHcSeM= github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/goconvey v1.6.4 h1:fv0U8FUIMPNf1L9lnHLvLhgicrIVChEkdzIKYqbNC9s= @@ -824,8 +824,8 @@ github.com/yuin/gopher-lua v1.1.1 h1:kYKnWBjvbNP4XLT3+bPEwAXJx262OhaHDWDVOPjL46M github.com/yuin/gopher-lua v1.1.1/go.mod h1:GBR0iDaNXjAgGg9zfCvksxSRnQx76gclCIb7kdAd1Pw= github.com/zitadel/exifremove v0.1.0 h1:qD50ezWsfeeqfcvs79QyyjVfK+snN12v0U0deaU8aKg= github.com/zitadel/exifremove v0.1.0/go.mod h1:rzKJ3woL/Rz2KthVBiSBKIBptNTvgmk9PLaeUKTm+ek= -github.com/zitadel/logging v0.6.2 h1:MW2kDDR0ieQynPZ0KIZPrh9ote2WkxfBif5QoARDQcU= -github.com/zitadel/logging v0.6.2/go.mod h1:z6VWLWUkJpnNVDSLzrPSQSQyttysKZ6bCRongw0ROK4= +github.com/zitadel/logging v0.7.0 h1:eugftwMM95Wgqwftsvj81isL0JK/hoScVqp/7iA2adQ= +github.com/zitadel/logging v0.7.0/go.mod h1:9A6h9feBF/3u0IhA4uffdzSDY7mBaf7RE78H5sFMINQ= github.com/zitadel/oidc/v3 v3.45.0 h1:SaVJ2kdcJi/zdEWWlAns+81VxmfdYX4E+2mWFVIH7Ec= github.com/zitadel/oidc/v3 v3.45.0/go.mod h1:UeK0iVOoqfMuDVgSfv56BqTz8YQC2M+tGRIXZ7Ii3VY= github.com/zitadel/passwap v0.10.0 h1:aB8qjUzQHW1tz3ebqv8nEJpeJw00sAy+xLasU7nxt34= @@ -1025,11 +1025,10 @@ golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20211019181941-9d821ace8654/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20211025201205-69cdffdb9359/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.39.0 h1:CvCKL8MeisomCi6qNZ+wbb0DN9E5AATixKsvNtMoMFk= -golang.org/x/sys v0.39.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks= +golang.org/x/sys v0.40.0 h1:DBZZqJ2Rkml6QMQsZywtnjnnGvHza6BTfYFWY9kjEWQ= +golang.org/x/sys v0.40.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk= diff --git a/internal/api/authz/instance.go b/internal/api/authz/instance.go index d51c2d8b9..2639ea124 100644 --- a/internal/api/authz/instance.go +++ b/internal/api/authz/instance.go @@ -6,6 +6,7 @@ import ( "golang.org/x/text/language" + "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/internal/execution/target" "github.com/zitadel/zitadel/internal/feature" ) @@ -107,11 +108,12 @@ func GetFeatures(ctx context.Context) feature.Features { } func WithInstance(ctx context.Context, instance Instance) context.Context { + ctx = instrumentation.SetInstance(ctx, instance) return context.WithValue(ctx, instanceKey, instance) } func WithInstanceID(ctx context.Context, id string) context.Context { - return context.WithValue(ctx, instanceKey, &instance{id: id}) + return WithInstance(ctx, &instance{id: id}) } func WithDefaultLanguage(ctx context.Context, defaultLanguage language.Tag) context.Context { diff --git a/internal/api/grpc/gerrors/zitadel_errors.go b/internal/api/grpc/gerrors/zitadel_errors.go index 967302021..3a9c6d7a2 100644 --- a/internal/api/grpc/gerrors/zitadel_errors.go +++ b/internal/api/grpc/gerrors/zitadel_errors.go @@ -7,13 +7,12 @@ import ( "connectrpc.com/connect" "github.com/jackc/pgx/v5/pgconn" - slogctx "github.com/veqryn/slog-context" - "github.com/zitadel/logging" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" "google.golang.org/protobuf/proto" "google.golang.org/protobuf/protoadapt" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" commandErrors "github.com/zitadel/zitadel/internal/command/errors" "github.com/zitadel/zitadel/internal/zerrors" "github.com/zitadel/zitadel/pkg/grpc/message" @@ -27,13 +26,13 @@ func ZITADELToGRPCError(ctx context.Context, err error) error { code, key, id, lvl := extractError(err) msg := key msg += " (" + id + ")" - slogctx.FromCtx(ctx).Log(ctx, lvl, msg, "err", err, "code", code) + logging.Log(ctx, lvl, msg, "err", err, "code", code) errorInfo := getErrorInfo(id, key, err) s, err := status.New(code, msg).WithDetails(errorInfo) if err != nil { - logging.WithError(err).WithField("logID", "GRPC-gIeRw").Debug("unable to add detail") + logging.WithError(ctx, err).Debug("unable to add error detail") return status.New(code, msg).Err() } @@ -48,13 +47,13 @@ func ZITADELToConnectError(ctx context.Context, err error) error { if errors.As(err, &connectError) { // Connect error may be returned by other middlewares, // so we assume it's a client error and log as warning. - slogctx.FromCtx(ctx).WarnContext(ctx, connectError.Message(), "err", connectError.Unwrap(), "code", connectError.Code()) + logging.Warn(ctx, connectError.Message(), "err", connectError.Unwrap(), "code", connectError.Code()) return err } code, key, id, lvl := extractError(err) msg := key msg += " (" + id + ")" - slogctx.FromCtx(ctx).Log(ctx, lvl, msg, "err", err) + logging.Log(ctx, lvl, msg, "err", err) errorInfo := getErrorInfo(id, key, err) diff --git a/internal/api/grpc/server/connect_middleware/log_interceptor.go b/internal/api/grpc/server/connect_middleware/log_interceptor.go index 564cf9c8f..a3d33d529 100644 --- a/internal/api/grpc/server/connect_middleware/log_interceptor.go +++ b/internal/api/grpc/server/connect_middleware/log_interceptor.go @@ -1,13 +1,55 @@ package connect_middleware import ( + "context" + "log/slog" + "slices" + "strings" + "time" + "connectrpc.com/connect" + "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" + http_util "github.com/zitadel/zitadel/internal/api/http" ) -func LogHandler(ignoredPrefix ...string) connect.UnaryInterceptorFunc { +func LogHandler(ignoredMethodSuffixes ...string) connect.UnaryInterceptorFunc { return func(next connect.UnaryFunc) connect.UnaryFunc { - return logging.NewConnectInterceptor(next, ignoredPrefix...) + return func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) { + if slices.ContainsFunc(ignoredMethodSuffixes, func(s string) bool { + return strings.HasSuffix(req.Spec().Procedure, s) + }) { + return next(ctx, req) + } + start := time.Now() + ctx = logging.NewCtx(ctx, logging.StreamRequest) + ctx = instrumentation.SetRequestID(ctx, start) + + resp, err := next(ctx, req) + var code connect.Code + if err != nil { + code = connect.CodeOf(err) + } + spec := req.Spec() + logging.Info(ctx, "request served", + slog.String("protocol", "connect"), + slog.Any("domain", http_util.DomainContext(ctx)), + slog.String("service", serviceFromRPCMethod(spec.Procedure)), + slog.String("http_method", req.HTTPMethod()), + slog.String("path", spec.Procedure), + slog.Any("code", code), + slog.Duration("duration", time.Since(start)), + ) + return resp, err + } } } + +func serviceFromRPCMethod(fullMethod string) string { + parts := strings.Split(fullMethod, "/") + if len(parts) >= 2 { + return parts[1] + } + return "unknown" +} diff --git a/internal/api/grpc/server/gateway.go b/internal/api/grpc/server/gateway.go index a9b705e53..5fa344ec1 100644 --- a/internal/api/grpc/server/gateway.go +++ b/internal/api/grpc/server/gateway.go @@ -284,5 +284,4 @@ func setRequestURIPattern(ctx context.Context) { } span := trace.SpanFromContext(ctx) span.SetName(pattern) - metrics.SetRequestURIPattern(ctx, pattern) } diff --git a/internal/api/grpc/server/middleware/log_interceptor.go b/internal/api/grpc/server/middleware/log_interceptor.go index 4b58b5291..ee5bedab1 100644 --- a/internal/api/grpc/server/middleware/log_interceptor.go +++ b/internal/api/grpc/server/middleware/log_interceptor.go @@ -1,11 +1,55 @@ package middleware import ( - "google.golang.org/grpc" + "context" + "log/slog" + "net/http" + "slices" + "strings" + "time" + "google.golang.org/grpc" + "google.golang.org/grpc/codes" + "google.golang.org/grpc/status" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" + http_util "github.com/zitadel/zitadel/internal/api/http" ) func LogHandler(ignoredMethodSuffixes ...string) grpc.UnaryServerInterceptor { - return logging.NewGrpcInterceptor(ignoredMethodSuffixes...) + return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, next grpc.UnaryHandler) (any, error) { + if slices.ContainsFunc(ignoredMethodSuffixes, func(s string) bool { + return strings.HasSuffix(info.FullMethod, s) + }) { + return next(ctx, req) + } + start := time.Now() + ctx = logging.NewCtx(ctx, logging.StreamRequest) + ctx = instrumentation.SetRequestID(ctx, start) + + resp, err := next(ctx, req) + var code codes.Code + if err != nil { + code = status.Code(err) + } + logging.Info(ctx, "request served", + slog.String("protocol", "grpc"), + slog.Any("domain", http_util.DomainContext(ctx)), + slog.String("service", serviceFromRPCMethod(info.FullMethod)), + slog.String("http_method", http.MethodPost), // gRPC always uses POST + slog.String("path", info.FullMethod), + slog.Any("code", code), + slog.Duration("duration", time.Since(start)), + ) + return resp, err + } +} + +func serviceFromRPCMethod(fullMethod string) string { + parts := strings.Split(fullMethod, "/") + if len(parts) >= 2 { + return parts[1] + } + return "unknown" } diff --git a/internal/api/http/error.go b/internal/api/http/error.go index e34524943..e544b119a 100644 --- a/internal/api/http/error.go +++ b/internal/api/http/error.go @@ -5,8 +5,7 @@ import ( "log/slog" "net/http" - slogctx "github.com/veqryn/slog-context" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/zerrors" ) @@ -17,7 +16,7 @@ func ZitadelErrorToHTTPStatusCode(ctx context.Context, err error) (statusCode in statusCode, key, id, lvl := extractError(err) msg := key msg += " (" + id + ")" - slogctx.FromCtx(ctx).Log(ctx, lvl, msg, "err", err) + logging.Log(ctx, lvl, msg, "err", err) if statusCode == statusUnknown { return http.StatusInternalServerError, false } diff --git a/internal/api/http/middleware/access_interceptor.go b/internal/api/http/middleware/access_interceptor.go index f09d0a4d4..b81fe7b99 100644 --- a/internal/api/http/middleware/access_interceptor.go +++ b/internal/api/http/middleware/access_interceptor.go @@ -133,7 +133,7 @@ func (a *AccessInterceptor) handle(publicAuthPathPrefixes ...string) func(http.H return http.HandlerFunc(func(writer http.ResponseWriter, request *http.Request) { ctx := request.Context() tracingCtx, checkSpan := tracing.NewNamedSpan(ctx, "checkAccessQuota") - wrappedWriter := &statusRecorder{ResponseWriter: writer, status: 0} + wrappedWriter := newStatusWriter(writer) limited := a.Limit(wrappedWriter, request.WithContext(tracingCtx), publicAuthPathPrefixes...) checkSpan.End() if limited { @@ -151,7 +151,7 @@ func (a *AccessInterceptor) handle(publicAuthPathPrefixes ...string) func(http.H } } -func (a *AccessInterceptor) writeLog(ctx context.Context, wrappedWriter *statusRecorder, writer http.ResponseWriter, request *http.Request, notCountable bool) { +func (a *AccessInterceptor) writeLog(ctx context.Context, wrappedWriter *statusWriter, writer http.ResponseWriter, request *http.Request, notCountable bool) { if !a.logstoreSvc.Enabled() { return } @@ -178,17 +178,3 @@ func (a *AccessInterceptor) writeLog(ctx context.Context, wrappedWriter *statusR NotCountable: notCountable, }) } - -type statusRecorder struct { - http.ResponseWriter - status int - ignoreWrites bool -} - -func (r *statusRecorder) WriteHeader(status int) { - if r.ignoreWrites { - return - } - r.status = status - r.ResponseWriter.WriteHeader(status) -} diff --git a/internal/api/http/middleware/log_interceptor.go b/internal/api/http/middleware/log_interceptor.go index f36f09b30..c81ee01c8 100644 --- a/internal/api/http/middleware/log_interceptor.go +++ b/internal/api/http/middleware/log_interceptor.go @@ -1,13 +1,39 @@ package middleware import ( + "log/slog" "net/http" + "time" + "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" + http_util "github.com/zitadel/zitadel/internal/api/http" ) func LogHandler(service string, ignoredPrefix ...string) func(http.Handler) http.Handler { - return func(h http.Handler) http.Handler { - return logging.NewHandler(h, service, ignoredPrefix...) + return func(next http.Handler) http.Handler { + filter := instrumentation.RequestFilter(ignoredPrefix...) + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if !filter(r) { + next.ServeHTTP(w, r) + return + } + start := time.Now() + ctx := logging.NewCtx(r.Context(), logging.StreamRequest) + ctx = instrumentation.SetRequestID(ctx, start) + sw := newStatusWriter(w) + + next.ServeHTTP(sw, r.WithContext(ctx)) + + logging.Info(ctx, "request served", + slog.String("protocol", "http"), + slog.Any("domain", http_util.DomainContext(ctx)), + slog.String("service", service), + slog.String("http_method", r.Method), // gRPC always uses POST + slog.String("path", r.URL.Path), + slog.Int("status", sw.status), + slog.Duration("duration", time.Since(start)), + ) + }) } } diff --git a/internal/api/http/middleware/metrics_interceptor.go b/internal/api/http/middleware/metrics_interceptor.go index 832f04c2d..d75994806 100644 --- a/internal/api/http/middleware/metrics_interceptor.go +++ b/internal/api/http/middleware/metrics_interceptor.go @@ -3,11 +3,57 @@ package middleware import ( "net/http" + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/metrics" ) func MetricsHandler(metricTypes []metrics.MetricType, ignoredMethods ...string) func(http.Handler) http.Handler { return func(handler http.Handler) http.Handler { - return metrics.NewHandler(handler, metricTypes, ignoredMethods...) + return &Handler{ + handler: handler, + methods: metricTypes, + filter: instrumentation.RequestFilter(ignoredMethods...), + } } } + +type Handler struct { + handler http.Handler + methods []metrics.MetricType + filter otelhttp.Filter +} + +// ServeHTTP implements [http.Handler] +func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + if len(h.methods) == 0 { + h.handler.ServeHTTP(w, r) + return + } + if !h.filter(r) { + // Simply pass through to the handler if a filter rejects the request + h.handler.ServeHTTP(w, r) + return + } + recorder := newStatusWriter(w) + h.handler.ServeHTTP(recorder, r) + if h.containsMetricsMethod(metrics.MetricTypeRequestCount) { + metrics.RegisterRequestCounter(recorder, r) + } + if h.containsMetricsMethod(metrics.MetricTypeTotalCount) { + metrics.RegisterTotalRequestCounter(r) + } + if h.containsMetricsMethod(metrics.MetricTypeStatusCode) { + metrics.RegisterRequestCodeCounter(recorder, r) + } +} + +func (h *Handler) containsMetricsMethod(method metrics.MetricType) bool { + for _, m := range h.methods { + if m == method { + return true + } + } + return false +} diff --git a/internal/api/http/middleware/middleware.go b/internal/api/http/middleware/middleware.go new file mode 100644 index 000000000..3a2795053 --- /dev/null +++ b/internal/api/http/middleware/middleware.go @@ -0,0 +1,29 @@ +package middleware + +import "net/http" + +// statusWriter is a [http.ResponseWriter] that captures the status code for logging. +type statusWriter struct { + http.ResponseWriter + status int +} + +func newStatusWriter(w http.ResponseWriter) *statusWriter { + return &statusWriter{ResponseWriter: w} +} + +func (w *statusWriter) Write(p []byte) (int, error) { + if w.status == 0 { + w.status = http.StatusOK + } + return w.ResponseWriter.Write(p) +} + +func (w *statusWriter) WriteHeader(statusCode int) { + w.status = statusCode + w.ResponseWriter.WriteHeader(statusCode) +} + +func (w *statusWriter) Status() int { + return w.status +} diff --git a/internal/api/http/middleware/middleware_test.go b/internal/api/http/middleware/middleware_test.go index 60d4099e0..6b41c5c14 100644 --- a/internal/api/http/middleware/middleware_test.go +++ b/internal/api/http/middleware/middleware_test.go @@ -1,9 +1,12 @@ package middleware import ( + "net/http/httptest" "os" "testing" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" "golang.org/x/text/language" "github.com/zitadel/zitadel/internal/i18n" @@ -17,3 +20,38 @@ func TestMain(m *testing.M) { i18n.SupportLanguages(SupportedLanguages...) os.Exit(m.Run()) } + +func Test_statusWriter(t *testing.T) { + tests := []struct { + name string + writeStatus int + wantStatus int + }{ + { + name: "default status is 200", + wantStatus: 200, + }, + { + name: "writes status code and body correctly", + writeStatus: 201, + wantStatus: 201, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + const body = "Hello, World!" + rec := httptest.NewRecorder() + sw := newStatusWriter(rec) + if tt.writeStatus != 0 { + sw.WriteHeader(tt.writeStatus) + } + _, err := sw.Write([]byte(body)) + require.NoError(t, err) + assert.Equal(t, tt.wantStatus, sw.Status()) + + resp := rec.Result() + assert.Equal(t, tt.wantStatus, resp.StatusCode) + assert.Equal(t, body, rec.Body.String()) + }) + } +} diff --git a/internal/api/http/middleware/trace_interceptor.go b/internal/api/http/middleware/trace_interceptor.go index 44a6f7e20..cf39be15d 100644 --- a/internal/api/http/middleware/trace_interceptor.go +++ b/internal/api/http/middleware/trace_interceptor.go @@ -3,7 +3,10 @@ package middleware import ( "net/http" - "github.com/zitadel/zitadel/backend/v3/instrumentation/tracing" + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + "go.opentelemetry.io/otel" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" http_utils "github.com/zitadel/zitadel/internal/api/http" ) @@ -13,6 +16,16 @@ func DefaultTraceHandler(handler http.Handler) http.Handler { func TraceHandler(ignoredPrefix ...string) func(http.Handler) http.Handler { return func(handler http.Handler) http.Handler { - return tracing.NewHandler(handler, ignoredPrefix...) + return otelhttp.NewHandler(handler, + "zitadel", + otelhttp.WithFilter(instrumentation.RequestFilter(ignoredPrefix...)), + otelhttp.WithPublicEndpoint(), + otelhttp.WithSpanNameFormatter(spanNameFormatter), + otelhttp.WithMeterProvider(otel.GetMeterProvider()), + ) } } + +func spanNameFormatter(_ string, r *http.Request) string { + return r.URL.Path +} diff --git a/internal/api/ui/login/external_provider_handler.go b/internal/api/ui/login/external_provider_handler.go index 7ccc0e39f..611d795a1 100644 --- a/internal/api/ui/login/external_provider_handler.go +++ b/internal/api/ui/login/external_provider_handler.go @@ -1611,5 +1611,5 @@ func WrapIdPError(err error) *IdPError { if errors.As(err, &zErr) { id = zErr.ID } - return &IdPError{err: zerrors.CreateZitadelError(zerrors.KindPreconditionFailed, err, id, "Errors.User.ExternalIDP.LoginFailedSwitchLocal")} + return &IdPError{err: zerrors.CreateZitadelError(zerrors.KindPreconditionFailed, err, id, "Errors.User.ExternalIDP.LoginFailedSwitchLocal", 1)} } diff --git a/internal/eventstore/event.go b/internal/eventstore/event.go index 656a02f33..fba50d1da 100644 --- a/internal/eventstore/event.go +++ b/internal/eventstore/event.go @@ -2,7 +2,10 @@ package eventstore import ( "encoding/json" + "log/slog" + "maps" "reflect" + "slices" "time" "github.com/shopspring/decimal" @@ -109,3 +112,58 @@ func isEventTypes(command Command, types ...EventType) bool { } return false } + +type logValue struct { + event Event +} + +func eventToLogValue(event Event) slog.LogValuer { + return &logValue{ + event: event, + } +} + +func (lv *logValue) LogValue() slog.Value { + attributes := make([]slog.Attr, 0, 12) + aggregate := lv.event.Aggregate() + attributes = append(attributes, + slog.String("aggregate_id", aggregate.ID), + slog.String("aggregate_type", string(aggregate.Type)), + slog.String("resource_owner", aggregate.ResourceOwner), + slog.String("instance_id", aggregate.InstanceID), + slog.String("version", string(aggregate.Version)), + slog.String("creator", lv.event.Creator()), + slog.String("event_type", string(lv.event.Type())), + slog.Uint64("revision", uint64(lv.event.Revision())), + slog.Uint64("sequence", lv.event.Sequence()), + slog.Time("created_at", lv.event.CreatedAt()), + slog.String("position", lv.event.Position().String()), + ) + + var m map[string]any + err := lv.event.Unmarshal(&m) + if err != nil { + attributes = append(attributes, + slog.String("msg", "failed to unmarshal event for logging"), + slog.String("err", err.Error()), + ) + return slog.GroupValue(attributes...) + } + attributes = append(attributes, + slog.Any("data", mapToLogValue(m)), + ) + return slog.GroupValue(attributes...) +} + +// mapToLogValue converts a map[string]any to a [slog.Value], handling nested maps recursively. +func mapToLogValue(m map[string]any) slog.Value { + attributes := make([]slog.Attr, 0, len(m)) + for _, key := range slices.Sorted(maps.Keys(m)) { + value := m[key] + if nestedMap, ok := value.(map[string]any); ok { + value = mapToLogValue(nestedMap) + } + attributes = append(attributes, slog.Any(key, value)) + } + return slog.GroupValue(attributes...) +} diff --git a/internal/eventstore/event_test.go b/internal/eventstore/event_test.go new file mode 100644 index 000000000..57fcdda20 --- /dev/null +++ b/internal/eventstore/event_test.go @@ -0,0 +1,139 @@ +package eventstore + +import ( + "log/slog" + "testing" + "time" + + "github.com/shopspring/decimal" + "github.com/stretchr/testify/assert" +) + +func Test_logValue_LogValue(t *testing.T) { + tests := []struct { + name string + event *BaseEvent + want slog.Value + }{ + { + name: "output event", + event: &BaseEvent{ + EventType: "test.type", + Agg: &Aggregate{ + ID: "agg-id", + Type: "agg-type", + ResourceOwner: "owner", + InstanceID: "instance-1", + Version: "x.y.z", + }, + Seq: 42, + Pos: decimal.NewFromInt(1001), + Creation: time.Unix(123, 456), + User: "user-123", + Data: []byte(`{"key1":"value1", "key2":"value2"}`), + }, + want: slog.GroupValue( + slog.String("aggregate_id", "agg-id"), + slog.String("aggregate_type", "agg-type"), + slog.String("resource_owner", "owner"), + slog.String("instance_id", "instance-1"), + slog.String("version", "x.y.z"), + slog.String("creator", "user-123"), + slog.String("event_type", "test.type"), + slog.Uint64("revision", uint64(0)), + slog.Uint64("sequence", 42), + slog.Time("created_at", time.Unix(123, 456)), + slog.String("position", "1001"), + slog.Any("data", slog.GroupValue( + slog.String("key1", "value1"), + slog.String("key2", "value2"), + )), + ), + }, + { + name: "unmarshal error", + event: &BaseEvent{ + EventType: "test.type", + Agg: &Aggregate{ + ID: "agg-id", + Type: "agg-type", + ResourceOwner: "owner", + InstanceID: "instance-1", + Version: "x.y.z", + }, + Seq: 42, + Pos: decimal.NewFromInt(1001), + Creation: time.Unix(123, 456), + User: "user-123", + Data: []byte(`invalid-json`), + }, + want: slog.GroupValue( + slog.String("aggregate_id", "agg-id"), + slog.String("aggregate_type", "agg-type"), + slog.String("resource_owner", "owner"), + slog.String("instance_id", "instance-1"), + slog.String("version", "x.y.z"), + slog.String("creator", "user-123"), + slog.String("event_type", "test.type"), + slog.Uint64("revision", uint64(0)), + slog.Uint64("sequence", 42), + slog.Time("created_at", time.Unix(123, 456)), + slog.String("position", "1001"), + slog.String("msg", "failed to unmarshal event for logging"), + slog.String("err", "invalid character 'i' looking for beginning of value"), + ), + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + lv := eventToLogValue(tt.event) + got := lv.LogValue() + assert.Equal(t, tt.want, got) + }) + } +} + +func Test_mapToLogValue(t *testing.T) { + tests := []struct { + name string + m map[string]any + want slog.Value + }{ + { + name: "flat map", + m: map[string]any{ + "key1": "value1", + "key2": 42, + "key3": true, + }, + want: slog.GroupValue( + slog.String("key1", "value1"), + slog.Int("key2", 42), + slog.Bool("key3", true), + ), + }, + { + name: "nested map", + m: map[string]any{ + "key1": "value1", + "key2": map[string]any{ + "nestedKey1": 3.14, + "nestedKey2": "nestedValue", + }, + }, + want: slog.GroupValue( + slog.String("key1", "value1"), + slog.Any("key2", slog.GroupValue( + slog.Float64("nestedKey1", 3.14), + slog.String("nestedKey2", "nestedValue"), + )), + ), + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := mapToLogValue(tt.m) + assert.Equal(t, tt.want, got) + }) + } +} diff --git a/internal/eventstore/eventstore.go b/internal/eventstore/eventstore.go index b9be38e8c..98f8150b1 100644 --- a/internal/eventstore/eventstore.go +++ b/internal/eventstore/eventstore.go @@ -4,13 +4,14 @@ import ( "context" "database/sql" "errors" + "log/slog" "sort" "time" "github.com/jackc/pgx/v5/pgconn" "github.com/shopspring/decimal" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" new_db "github.com/zitadel/zitadel/backend/v3/storage/database" new_sql "github.com/zitadel/zitadel/backend/v3/storage/database/dialect/sql" "github.com/zitadel/zitadel/internal/api/authz" @@ -33,6 +34,8 @@ type Eventstore struct { pusher Pusher querier Querier searcher Searcher + + logger *slog.Logger } var ( @@ -73,6 +76,7 @@ func NewEventstore(config *Config) *Eventstore { pusher: config.Pusher, querier: config.Querier, searcher: config.Searcher, + logger: logging.New(logging.StreamEventPusher), } } @@ -107,21 +111,27 @@ func (es *Eventstore) PushWithClient(ctx context.Context, client database.Contex } func (es *Eventstore) PushWithNewClient(ctx context.Context, client new_db.QueryExecutor, cmds ...Command) ([]Event, error) { + ctx = logging.ToCtx(ctx, es.logger) if es.PushTimeout > 0 { var cancel func() ctx, cancel = context.WithTimeout(ctx, es.PushTimeout) defer cancel() } var ( - events []Event - err error + events []Event + err error + retries int ) + defer func() { + logging.OnError(ctx, err).Error("eventstore push failed", "retries", retries) + logPushedEvents(ctx, events) + }() // Retry when there is a collision of the sequence as part of the primary key. // "duplicate key value violates unique constraint \"events2_pkey\" (SQLSTATE 23505)" // https://github.com/zitadel/zitadel/issues/7202 retry: - for i := 0; i <= es.maxRetries; i++ { + for ; retries <= es.maxRetries; retries++ { events, err = es.pusher.Push(ctx, client, cmds...) // if there is a transaction passed the calling function needs to retry if _, ok := client.(new_db.Transaction); ok { @@ -132,11 +142,11 @@ retry: break retry } if pgErr.ConstraintName == "events2_pkey" && pgErr.SQLState() == "23505" { - logging.WithError(err).Info("eventstore push retry") + logging.WithError(ctx, err).Info("eventstore push retry") continue } if pgErr.SQLState() == "CR000" || pgErr.SQLState() == "40001" { - logging.WithError(err).Info("eventstore push retry") + logging.WithError(ctx, err).Info("eventstore push retry") continue } break retry @@ -334,3 +344,9 @@ func appendAggregateType(typ AggregateType) { } aggregateTypes = append(aggregateTypes[:i], append([]string{string(typ)}, aggregateTypes[i:]...)...) } + +func logPushedEvents(ctx context.Context, events []Event) { + for _, event := range events { + logging.Info(ctx, "event pushed", "event", eventToLogValue(event)) + } +} diff --git a/internal/eventstore/handler/v2/failed_event.go b/internal/eventstore/handler/v2/failed_event.go index cee1bbc77..46f2df0fb 100644 --- a/internal/eventstore/handler/v2/failed_event.go +++ b/internal/eventstore/handler/v2/failed_event.go @@ -1,10 +1,13 @@ package handler import ( + "context" "database/sql" _ "embed" + "log/slog" "time" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/zerrors" ) @@ -25,6 +28,14 @@ type failure struct { err error } +func (f *failure) LogValue() slog.Value { + return slog.GroupValue( + slog.Uint64("sequence", f.sequence), + slog.String("instance", f.instance), + slog.String("aggregate_id", f.aggregateID), + ) +} + func failureFromEvent(event eventstore.Event, err error) *failure { return &failure{ sequence: event.Sequence(), @@ -47,15 +58,16 @@ func failureFromStatement(statement *Statement, err error) *failure { } } -func (h *Handler) handleFailedStmt(tx *sql.Tx, f *failure) (shouldContinue bool) { +func (h *Handler) handleFailedStmt(ctx context.Context, tx *sql.Tx, f *failure) (shouldContinue bool) { + ctx = logging.With(ctx, "failure", f) failureCount, err := h.failureCount(tx, f) if err != nil { - h.logFailure(f).WithError(err).Warn("unable to get failure count") + logging.Warn(ctx, "unable to get failure count", "err", err) return false } failureCount += 1 err = h.setFailureCount(tx, failureCount, f) - h.logFailure(f).OnError(err).Warn("unable to update failure count") + logging.OnError(ctx, err).Warn("unable to update failure count") return failureCount >= h.maxFailureCount } diff --git a/internal/eventstore/handler/v2/field_handler.go b/internal/eventstore/handler/v2/field_handler.go index 9d350e016..957a9c0dd 100644 --- a/internal/eventstore/handler/v2/field_handler.go +++ b/internal/eventstore/handler/v2/field_handler.go @@ -10,6 +10,7 @@ import ( "github.com/jackc/pgx/v5/pgconn" "github.com/shopspring/decimal" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/zerrors" @@ -79,8 +80,7 @@ func (h *FieldHandler) Trigger(ctx context.Context, opts ...TriggerOpt) (err err wg.Done() } wg.Wait() - h.log().OnError(err).Info("process events failed") - h.log().WithField("iteration", i).Debug("trigger iteration") + logging.Debug(ctx, "trigger iteration", "iteration", i) if !additionalIteration || err != nil { return err } @@ -93,7 +93,7 @@ func (h *FieldHandler) processEvents(ctx context.Context, config *triggerConfig) if errors.As(err, &pgErr) { // error returned if the row is currently locked by another connection if pgErr.Code == "55P03" { - h.log().Debug("state already locked") + logging.WithError(ctx, err).Info("another handler is already updating this projection") err = nil additionalIteration = false } @@ -117,7 +117,7 @@ func (h *FieldHandler) processEvents(ctx context.Context, config *triggerConfig) defer func() { if err != nil && !errors.Is(err, &executionError{}) { rollbackErr := tx.Rollback() - h.log().OnError(rollbackErr).Debug("unable to rollback tx") + logging.OnError(ctx, rollbackErr).Error("unable to rollback tx") return } commitErr := tx.Commit() @@ -156,7 +156,7 @@ func (h *FieldHandler) processEvents(ctx context.Context, config *triggerConfig) return additionalIteration, err } if len(events) == 0 { - err = h.setState(tx, currentState) + err = h.setState(ctx, tx, currentState) return additionalIteration, err } @@ -165,7 +165,7 @@ func (h *FieldHandler) processEvents(ctx context.Context, config *triggerConfig) return false, err } - err = h.setState(tx, currentState) + err = h.setState(ctx, tx, currentState) return additionalIteration, err } @@ -173,7 +173,7 @@ func (h *FieldHandler) processEvents(ctx context.Context, config *triggerConfig) func (h *FieldHandler) fetchEvents(ctx context.Context, tx *sql.Tx, currentState *state) (_ []eventstore.FillFieldsEvent, additionalIteration bool, err error) { events, err := h.es.Filter(ctx, h.eventQuery(currentState).SetTx(tx)) if err != nil || len(events) == 0 { - h.log().OnError(err).Debug("filter eventstore failed") + logging.OnError(ctx, err).Debug("filter eventstore failed") return nil, false, err } eventAmount := len(events) diff --git a/internal/eventstore/handler/v2/handler.go b/internal/eventstore/handler/v2/handler.go index 854f88151..593bdb8fb 100644 --- a/internal/eventstore/handler/v2/handler.go +++ b/internal/eventstore/handler/v2/handler.go @@ -4,15 +4,17 @@ import ( "context" "database/sql" "errors" + "log/slog" "math/rand" "slices" "sync" "time" "github.com/jackc/pgx/v5/pgconn" + "github.com/rs/xid" "github.com/shopspring/decimal" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/api/call" "github.com/zitadel/zitadel/internal/database" @@ -80,11 +82,12 @@ var _ migration.Migration = (*Handler)(nil) // Execute implements migration.Migration. func (h *Handler) Execute(ctx context.Context, startedEvent eventstore.Event) error { start := time.Now() - logging.WithFields("projection", h.ProjectionName()).Info("projection starts prefilling") + ctx = logging.With(ctx, "projection", h.ProjectionName()) + logging.Info(ctx, "projection starts prefilling") logTicker := time.NewTicker(30 * time.Second) go func() { for range logTicker.C { - logging.WithFields("projection", h.ProjectionName()).Info("projection is prefilling") + logging.Info(ctx, "projection is prefilling") } }() @@ -123,7 +126,7 @@ func (h *Handler) Execute(ctx context.Context, startedEvent eventstore.Event) er wg.Wait() logTicker.Stop() - logging.WithFields("projection", h.ProjectionName(), "took", time.Since(start)).Info("projections ended prefilling") + logging.Info(ctx, "projections ended prefilling", "took", time.Since(start)) return nil } @@ -170,7 +173,7 @@ func NewHandler( aggregates[reducer.Aggregate] = eventTypes } - metrics := NewProjectionMetrics() + metrics := NewProjectionMetrics(ctx) handler := &Handler{ projection: projection, @@ -203,6 +206,7 @@ func NewHandler( } func (h *Handler) Start(ctx context.Context) { + ctx = logging.NewCtx(ctx, logging.StreamEventHandler, slog.String("projection", h.ProjectionName())) go h.schedule(ctx) if h.triggerWithoutEvents != nil { return @@ -267,10 +271,12 @@ func (h *Handler) schedule(ctx context.Context) { t.Stop() return case <-t.C: + jobCtx := logging.With(ctx, "job_id", xid.New(), "invoker", "schedule") instances, err := h.queryInstances() - h.log().OnError(err).Debug("unable to query instances") - - h.triggerInstances(call.WithTimestamp(ctx), instances) + if err != nil { + logging.Debug(jobCtx, "unable to query instances", "err", err) + } + h.triggerInstances(call.WithTimestamp(jobCtx), instances) t.Reset(h.requeueEvery) } } @@ -286,12 +292,12 @@ func (h *Handler) triggerInstances(ctx context.Context, instances []string, trig if err == nil { continue } - h.log().WithField("instance", instance).WithError(err).Debug("trigger failed") + logging.Debug(instanceCtx, "trigger failed", "err", err) time.Sleep(h.retryFailedAfter) // retry if trigger failed for ; err != nil; _, err = h.Trigger(instanceCtx, triggerOpts...) { time.Sleep(h.retryFailedAfter) - h.log().WithField("instance", instance).WithError(err).Debug("trigger failed") + logging.Debug(instanceCtx, "trigger failed", "err", err) } } } @@ -302,28 +308,29 @@ func randomizeStart(min, maxSeconds float64) time.Duration { } func (h *Handler) subscribe(ctx context.Context) { + defer logging.Info(ctx, "handler has shutdown") queue := make(chan eventstore.Event, 100) subscription := eventstore.SubscribeEventTypes(queue, h.eventTypes) for { select { case <-ctx.Done(): subscription.Unsubscribe() - h.log().Debug("shutdown") return case event := <-queue: events := checkAdditionalEvents(queue, event) solvedInstances := make([]string, 0, len(events)) queueCtx := call.WithTimestamp(ctx) + queueCtx = logging.With(queueCtx, "job_id", xid.New(), "invoker", "subscribe") for _, e := range events { if slices.Contains(solvedInstances, e.Aggregate().InstanceID) { continue } queueCtx = authz.WithInstanceID(queueCtx, e.Aggregate().InstanceID) - _, err := h.Trigger(queueCtx) - h.log().OnError(err).Debug("trigger of queued event failed") - if err == nil { - solvedInstances = append(solvedInstances, e.Aggregate().InstanceID) + if _, err := h.Trigger(queueCtx); err != nil { + logging.Warn(queueCtx, "trigger of queued event failed", "err", err) + continue } + solvedInstances = append(solvedInstances, e.Aggregate().InstanceID) } } } @@ -468,8 +475,7 @@ func (h *Handler) Trigger(ctx context.Context, opts ...TriggerOpt) (_ context.Co wg.Done() } wg.Wait() - h.log().OnError(err).Info("process events failed") - h.log().WithField("iteration", i).Debug("trigger iteration") + logging.Debug(ctx, "trigger iteration", "iteration", i) if !additionalIteration || err != nil { return call.ResetTimestamp(ctx), err } @@ -523,7 +529,7 @@ func (h *Handler) processEvents(ctx context.Context, config *triggerConfig) (add if errors.As(err, &pgErr) { // error returned if the row is currently locked by another connection if pgErr.Code == "55P03" { - h.log().Debug("state already locked") + logging.WithError(ctx, err).Info("another handler is already updating this projection") err = nil additionalIteration = false } @@ -549,7 +555,7 @@ func (h *Handler) processEvents(ctx context.Context, config *triggerConfig) (add defer func() { if err != nil && !errors.Is(err, &executionError{}) { rollbackErr := tx.Rollback() - h.log().OnError(rollbackErr).Debug("unable to rollback tx") + logging.OnError(ctx, rollbackErr).Error("unable to rollback tx") return } commitErr := tx.Commit() @@ -569,7 +575,7 @@ func (h *Handler) processEvents(ctx context.Context, config *triggerConfig) (add return false, err } if !hasLocked { - h.log().Debug("skip execution, projection already locked") + logging.Info(ctx, "another handler is already updating this projection") return false, nil } @@ -611,12 +617,12 @@ func (h *Handler) processEvents(ctx context.Context, config *triggerConfig) (add }() if len(statements) == 0 { - err = h.setState(tx, currentState) + err = h.setState(ctx, tx, currentState) return additionalIteration, err } lastProcessedIndex, err := h.executeStatements(ctx, tx, statements) - h.log().OnError(err).WithField("lastProcessedIndex", lastProcessedIndex).Debug("execution of statements failed") + logging.OnError(ctx, err).Debug("execution of statements failed", "lastProcessedIndex", lastProcessedIndex) if lastProcessedIndex < 0 { return false, err } @@ -628,7 +634,7 @@ func (h *Handler) processEvents(ctx context.Context, config *triggerConfig) (add currentState.sequence = statements[lastProcessedIndex].Sequence currentState.eventTimestamp = statements[lastProcessedIndex].CreationDate - setStateErr := h.setState(tx, currentState) + setStateErr := h.setState(ctx, tx, currentState) if setStateErr != nil { err = setStateErr } @@ -647,12 +653,12 @@ func (h *Handler) generateStatements(ctx context.Context, tx *sql.Tx, currentSta events, err := h.es.Filter(ctx, h.eventQuery(currentState).SetTx(tx)) if err != nil { - h.log().WithError(err).Debug("filter eventstore failed") + logging.WithError(ctx, err).Debug("filter eventstore failed") return nil, false, err } eventAmount := len(events) - statements, err := h.eventsToStatements(tx, events, currentState) + statements, err := h.eventsToStatements(ctx, tx, events, currentState) if err != nil || len(statements) == 0 { return nil, false, err } @@ -716,17 +722,17 @@ func (h *Handler) executeStatement(ctx context.Context, tx *sql.Tx, statement *S _, err = tx.ExecContext(ctx, "SAVEPOINT exec_stmt") if err != nil { - h.log().WithError(err).Debug("create savepoint failed") + logging.WithError(ctx, err).Debug("create savepoint failed") return err } if err = statement.Execute(ctx, tx, h.projection.Name()); err != nil { - h.log().WithError(err).Error("statement execution failed") + logging.WithError(ctx, err).Error("statement execution failed") _, rollbackErr := tx.ExecContext(ctx, "ROLLBACK TO SAVEPOINT exec_stmt") - h.log().OnError(rollbackErr).Error("rollback to savepoint failed") + logging.OnError(ctx, rollbackErr).Debug("rollback to savepoint failed") - shouldContinue := h.handleFailedStmt(tx, failureFromStatement(statement, err)) + shouldContinue := h.handleFailedStmt(ctx, tx, failureFromStatement(statement, err)) if shouldContinue { return nil } diff --git a/internal/eventstore/handler/v2/init.go b/internal/eventstore/handler/v2/init.go index f79773464..2c32e5a2a 100644 --- a/internal/eventstore/handler/v2/init.go +++ b/internal/eventstore/handler/v2/init.go @@ -7,8 +7,8 @@ import ( "strings" "github.com/jackc/pgx/v5/pgconn" - "github.com/zitadel/logging" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/eventstore/handler" "github.com/zitadel/zitadel/internal/zerrors" ) @@ -198,15 +198,18 @@ func (h *Handler) Init(ctx context.Context) error { if err != nil { return zerrors.ThrowInternal(err, "CRDB-SAdf2", "begin failed") } + ctx = logging.With(ctx, "projection", h.ProjectionName()) for i, execute := range check.Init().Executes { - logging.WithFields("projection", h.projection.Name(), "execute", i).Debug("executing check") + logging.Debug(ctx, "executing check", "execute", i) next, err := execute(ctx, tx, h.projection.Name()) if err != nil { - logging.OnError(tx.Rollback()).Debug("unable to rollback") + if rollbackErr := tx.Rollback(); rollbackErr != nil { + logging.Error(ctx, "unable to rollback", "err", rollbackErr) + } return err } if !next { - logging.WithFields("projection", h.projection.Name(), "execute", i).Debug("projection set up") + logging.Debug(ctx, "projection set up", "execute", i) break } } diff --git a/internal/eventstore/handler/v2/log.go b/internal/eventstore/handler/v2/log.go deleted file mode 100644 index e9145dfb4..000000000 --- a/internal/eventstore/handler/v2/log.go +++ /dev/null @@ -1,23 +0,0 @@ -package handler - -import ( - "github.com/zitadel/logging" - - "github.com/zitadel/zitadel/internal/eventstore" -) - -func (h *Handler) log() *logging.Entry { - return logging.WithFields("projection", h.projection.Name()) -} - -func (h *Handler) logFailure(fail *failure) *logging.Entry { - return h.log().WithField("sequence", fail.sequence). - WithField("instance", fail.instance). - WithField("aggregate", fail.aggregateID) -} - -func (h *Handler) logEvent(event eventstore.Event) *logging.Entry { - return h.log().WithField("sequence", event.Sequence()). - WithField("instance", event.Aggregate().InstanceID). - WithField("aggregate", event.Aggregate().Type) -} diff --git a/internal/eventstore/handler/v2/metrics.go b/internal/eventstore/handler/v2/metrics.go index d3ac01fbb..9baf89322 100644 --- a/internal/eventstore/handler/v2/metrics.go +++ b/internal/eventstore/handler/v2/metrics.go @@ -3,9 +3,9 @@ package handler import ( "context" - "github.com/zitadel/logging" "go.opentelemetry.io/otel/attribute" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/backend/v3/instrumentation/metrics" ) @@ -22,32 +22,32 @@ type ProjectionMetrics struct { provider metrics.Metrics } -func NewProjectionMetrics() *ProjectionMetrics { - return newProjectionMetrics(metrics.GlobalMeter()) +func NewProjectionMetrics(ctx context.Context) *ProjectionMetrics { + return newProjectionMetrics(ctx, metrics.GlobalMeter()) } -func newProjectionMetrics(m metrics.Metrics) *ProjectionMetrics { +func newProjectionMetrics(ctx context.Context, m metrics.Metrics) *ProjectionMetrics { projectionMetrics := &ProjectionMetrics{provider: m} err := projectionMetrics.provider.RegisterCounter( ProjectionEventsProcessed, "Number of events reduced to process projection updates", ) - logging.OnError(err).Error("failed to register projection events processed counter") + logging.OnError(ctx, err).Error("failed to register projection events processed counter") err = projectionMetrics.provider.RegisterHistogram( ProjectionHandleTimerMetric, "Time taken to process a projection update", "s", []float64{0.005, 0.01, 0.05, 0.1, 1, 5, 10, 30, 60, 120}, ) - logging.OnError(err).Error("failed to register projection handle timer metric") + logging.OnError(ctx, err).Error("failed to register projection handle timer metric") err = projectionMetrics.provider.RegisterHistogram( ProjectionStateLatencyMetric, "When finishing processing a batch of events, this track the age of the last events seen from current time", "s", []float64{0.1, 0.5, 1, 5, 10, 30, 60, 300, 600, 1800}, ) - logging.OnError(err).Error("failed to register projection state latency metric") + logging.OnError(ctx, err).Error("failed to register projection state latency metric") return projectionMetrics } @@ -55,7 +55,7 @@ func (m *ProjectionMetrics) ProjectionUpdateTiming(ctx context.Context, projecti err := m.provider.AddHistogramMeasurement(ctx, ProjectionHandleTimerMetric, duration, map[string]attribute.Value{ ProjectionLabel: attribute.StringValue(projection), }) - logging.OnError(err).Error("failed to add projection trigger timing") + logging.OnError(ctx, err).Error("failed to add projection trigger timing") } func (m *ProjectionMetrics) ProjectionEventsProcessed(ctx context.Context, projection string, count int64, success bool) { @@ -63,12 +63,12 @@ func (m *ProjectionMetrics) ProjectionEventsProcessed(ctx context.Context, proje ProjectionLabel: attribute.StringValue(projection), SuccessLabel: attribute.BoolValue(success), }) - logging.OnError(err).Error("failed to add projection events processed metric") + logging.OnError(ctx, err).Error("failed to add projection events processed metric") } func (m *ProjectionMetrics) ProjectionStateLatency(ctx context.Context, projection string, latency float64) { err := m.provider.AddHistogramMeasurement(ctx, ProjectionStateLatencyMetric, latency, map[string]attribute.Value{ ProjectionLabel: attribute.StringValue(projection), }) - logging.OnError(err).Error("failed to add projection state latency metric") + logging.OnError(ctx, err).Error("failed to add projection state latency metric") } diff --git a/internal/eventstore/handler/v2/metrics_test.go b/internal/eventstore/handler/v2/metrics_test.go index e72b1b74b..a4d6a17d2 100644 --- a/internal/eventstore/handler/v2/metrics_test.go +++ b/internal/eventstore/handler/v2/metrics_test.go @@ -13,14 +13,14 @@ import ( func TestNewProjectionMetrics(t *testing.T) { mockMetrics := metrics.NewMockMetrics() - metrics := newProjectionMetrics(mockMetrics) + metrics := newProjectionMetrics(t.Context(), mockMetrics) require.NotNil(t, metrics) assert.NotNil(t, metrics.provider) } func TestProjectionMetrics_ProjectionUpdateTiming(t *testing.T) { mockMetrics := metrics.NewMockMetrics() - projectionMetrics := newProjectionMetrics(mockMetrics) + projectionMetrics := newProjectionMetrics(t.Context(), mockMetrics) ctx := context.Background() projection := "test_projection" @@ -39,7 +39,7 @@ func TestProjectionMetrics_ProjectionUpdateTiming(t *testing.T) { func TestProjectionMetrics_ProjectionEventsProcessed(t *testing.T) { mockMetrics := metrics.NewMockMetrics() - projectionMetrics := newProjectionMetrics(mockMetrics) + projectionMetrics := newProjectionMetrics(t.Context(), mockMetrics) ctx := context.Background() projection := "test_projection" @@ -59,7 +59,7 @@ func TestProjectionMetrics_ProjectionEventsProcessed(t *testing.T) { func TestProjectionMetrics_ProjectionStateLatency(t *testing.T) { mockMetrics := metrics.NewMockMetrics() - projectionMetrics := newProjectionMetrics(mockMetrics) + projectionMetrics := newProjectionMetrics(t.Context(), mockMetrics) ctx := context.Background() projection := "test_projection" @@ -78,7 +78,7 @@ func TestProjectionMetrics_ProjectionStateLatency(t *testing.T) { func TestProjectionMetrics_Integration(t *testing.T) { mockMetrics := metrics.NewMockMetrics() - projectionMetrics := newProjectionMetrics(mockMetrics) + projectionMetrics := newProjectionMetrics(t.Context(), mockMetrics) ctx := context.Background() projection := "test_projection" diff --git a/internal/eventstore/handler/v2/state.go b/internal/eventstore/handler/v2/state.go index 20febece7..5de452685 100644 --- a/internal/eventstore/handler/v2/state.go +++ b/internal/eventstore/handler/v2/state.go @@ -9,6 +9,7 @@ import ( "github.com/shopspring/decimal" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/api/authz" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/zerrors" @@ -55,7 +56,7 @@ func (h *Handler) currentState(ctx context.Context, tx *sql.Tx) (currentState *s offset, ) if err != nil && !errors.Is(err, sql.ErrNoRows) { - h.log().WithError(err).Debug("unable to query current state") + logging.WithError(ctx, err).Debug("unable to query current state") return nil, err } @@ -69,7 +70,7 @@ func (h *Handler) currentState(ctx context.Context, tx *sql.Tx) (currentState *s return currentState, nil } -func (h *Handler) setState(tx *sql.Tx, updatedState *state) error { +func (h *Handler) setState(ctx context.Context, tx *sql.Tx, updatedState *state) error { res, err := tx.Exec(updateStateStmt, h.projection.Name(), updatedState.instanceID, @@ -81,12 +82,14 @@ func (h *Handler) setState(tx *sql.Tx, updatedState *state) error { updatedState.offset, ) if err != nil { - h.log().WithError(err).Warn("unable to update state") - return zerrors.ThrowInternal(err, "V2-WF23g2", "unable to update state") + err = zerrors.ThrowInternal(err, "V2-WF23g2", "unable to update state") + logging.Warn(ctx, "unable to update state", "err", err) + return err } if affected, err := res.RowsAffected(); affected == 0 { - h.log().OnError(err).Error("unable to check if states are updated") - return zerrors.ThrowInternal(err, "V2-FGEKi", "unable to update state") + err = zerrors.ThrowInternal(err, "V2-FGEKi", "unable to update state") + logging.Error(ctx, "unable to check if states are updated", "err", err) + return err } return nil } diff --git a/internal/eventstore/handler/v2/state_test.go b/internal/eventstore/handler/v2/state_test.go index 309c5497f..f793f133f 100644 --- a/internal/eventstore/handler/v2/state_test.go +++ b/internal/eventstore/handler/v2/state_test.go @@ -137,7 +137,7 @@ func TestHandler_updateLastUpdated(t *testing.T) { h := &Handler{ projection: tt.fields.projection, } - err = h.setState(tx, tt.args.updatedState) + err = h.setState(t.Context(), tx, tt.args.updatedState) tt.isErr(t, err) tt.fields.mock.Assert(t) diff --git a/internal/eventstore/handler/v2/statement.go b/internal/eventstore/handler/v2/statement.go index 6f29a79f2..bad8a97b3 100644 --- a/internal/eventstore/handler/v2/statement.go +++ b/internal/eventstore/handler/v2/statement.go @@ -11,9 +11,9 @@ import ( "time" "github.com/shopspring/decimal" - "github.com/zitadel/logging" "golang.org/x/exp/constraints" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/zerrors" @@ -39,7 +39,7 @@ func (s *executionError) Unwrap() error { return s.parent } -func (h *Handler) eventsToStatements(tx *sql.Tx, events []eventstore.Event, currentState *state) (statements []*Statement, err error) { +func (h *Handler) eventsToStatements(ctx context.Context, tx *sql.Tx, events []eventstore.Event, currentState *state) (statements []*Statement, err error) { statements = make([]*Statement, 0, len(events)) previousPosition := currentState.position @@ -47,8 +47,8 @@ func (h *Handler) eventsToStatements(tx *sql.Tx, events []eventstore.Event, curr for _, event := range events { statement, err := h.reduce(event) if err != nil { - h.logEvent(event).WithError(err).Error("reduce failed") - if shouldContinue := h.handleFailedStmt(tx, failureFromEvent(event, err)); shouldContinue { + logging.Error(ctx, "reduce failed", "err", err, "event", failureFromEvent(event, err)) + if shouldContinue := h.handleFailedStmt(ctx, tx, failureFromEvent(event, err)); shouldContinue { continue } return statements, &executionError{err} @@ -577,7 +577,9 @@ func NewCol(name string, value interface{}) Column { func NewJSONCol(name string, value interface{}) Column { marshalled, err := json.Marshal(value) if err != nil { - logging.WithFields("column", name).WithError(err).Panic("unable to marshal column") + err = zerrors.ThrowInternal(err, "V2-aez5X", "unable to marshal column") + ctx := logging.NewCtx(context.Background(), logging.StreamEventHandler) + logging.OnError(ctx, err).Panic("unable to marshal column", "column", name, "err", err) } return NewCol(name, marshalled) diff --git a/internal/execution/projections.go b/internal/execution/projections.go index 0b336d4b2..de755a7e7 100644 --- a/internal/execution/projections.go +++ b/internal/execution/projections.go @@ -14,13 +14,14 @@ var ( ) func Register( + ctx context.Context, workerConfig WorkerConfig, queue *queue.Queue, targetEncAlg crypto.EncryptionAlgorithm, activeSigningKey GetActiveSigningWebKey, ) { queue.ShouldStart() - queue.AddWorkers(NewWorker(workerConfig, targetEncAlg, activeSigningKey, time.Now)) + queue.AddWorkers(ctx, NewWorker(workerConfig, targetEncAlg, activeSigningKey, time.Now)) } func Start(ctx context.Context) { diff --git a/internal/migration/migration.go b/internal/migration/migration.go index 3aeb2f061..cc5c9f000 100644 --- a/internal/migration/migration.go +++ b/internal/migration/migration.go @@ -5,8 +5,7 @@ import ( "errors" "time" - "github.com/zitadel/logging" - + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/eventstore" "github.com/zitadel/zitadel/internal/zerrors" ) @@ -43,7 +42,8 @@ type RepeatableMigration interface { } func Migrate(ctx context.Context, es *eventstore.Eventstore, migration Migration) (err error) { - logging.WithFields("name", migration.String()).Info("verify migration") + ctx = logging.With(ctx, "name", migration.String()) + logging.Info(ctx, "verify migration") continueOnErr := func(err error) bool { return false @@ -66,12 +66,12 @@ func Migrate(ctx context.Context, es *eventstore.Eventstore, migration Migration return err } - logging.WithFields("name", migration.String()).Info("starting migration") + logging.Info(ctx, "starting migration") err = migration.Execute(ctx, startedEvent[0]) - logging.WithFields("name", migration.String()).OnError(err).Error("migration failed") + logging.OnError(ctx, err).Error("migration failed") _, pushErr := es.Push(ctx, setupDoneCmd(ctx, migration, err)) - logging.WithFields("name", migration.String()).OnError(pushErr).Error("migration finish failed") + logging.OnError(ctx, pushErr).Error("migration finish failed") if err != nil { return err } @@ -129,8 +129,7 @@ func checkExec(ctx context.Context, es *eventstore.Eventstore, migration Migrati if !errors.Is(err, errMigrationAlreadyStarted) { return false, err } - logging.WithFields("migration step", migration.String()). - Warn("migration already started, will check again in 5 seconds") + logging.Warn(ctx, "migration already started, will check again in 5 seconds") timer.Reset(5 * time.Second) break } diff --git a/internal/notification/projections.go b/internal/notification/projections.go index 832e9ebf9..7ad8a23fb 100644 --- a/internal/notification/projections.go +++ b/internal/notification/projections.go @@ -57,12 +57,12 @@ func Register( queue, backChannelLogoutWorkerConfig.MaxAttempts, )) - queue.AddWorkers(handlers.NewBackChannelLogoutWorker(commands, q, es, queue, c, backChannelLogoutWorkerConfig, id.SonyFlakeGenerator())) + queue.AddWorkers(ctx, handlers.NewBackChannelLogoutWorker(commands, q, es, queue, c, backChannelLogoutWorkerConfig, id.SonyFlakeGenerator())) if telemetryCfg.Enabled { projections = append(projections, handlers.NewTelemetryPusher(ctx, telemetryCfg, projection.ApplyCustomConfig(telemetryHandlerCustomConfig), commands, q, c)) } if !notificationWorkerConfig.LegacyEnabled { - queue.AddWorkers(handlers.NewNotificationWorker(notificationWorkerConfig, commands, q, c)) + queue.AddWorkers(ctx, handlers.NewNotificationWorker(notificationWorkerConfig, commands, q, c)) } } diff --git a/internal/queue/log.go b/internal/queue/log.go new file mode 100644 index 000000000..f9a235023 --- /dev/null +++ b/internal/queue/log.go @@ -0,0 +1,106 @@ +package queue + +import ( + "context" + "encoding/hex" + "log/slog" + "time" + + "github.com/riverqueue/river" + "github.com/riverqueue/river/rivertype" + + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" +) + +type logMiddleware struct { + river.MiddlewareDefaults + logger *slog.Logger +} + +func newLogMiddleware() rivertype.Middleware { + return &logMiddleware{ + logger: logging.New(logging.StreamQueue), + } +} + +func (m *logMiddleware) InsertMany( + ctx context.Context, + manyParams []*rivertype.JobInsertParams, + doInner func(context.Context) ([]*rivertype.JobInsertResult, error), +) ([]*rivertype.JobInsertResult, error) { + start := time.Now() + ctx = logging.ToCtx(ctx, m.logger) + results, err := doInner(ctx) + if err != nil { + logging.WithError(ctx, err).Error("insert many error") + return results, err + } + logging.Debug(ctx, "jobs inserted", + slog.Int("count", len(results)), + slog.Duration("duration", time.Since(start)), + ) + + // Only do expensive operations if debug is enabled + if m.logger.Enabled(ctx, slog.LevelDebug) { + for _, result := range results { + logging.Debug(ctx, "inserted job details", attributesFromJobInsertResult(result)...) + } + } + return results, err +} + +func (m *logMiddleware) Work( + ctx context.Context, + job *rivertype.JobRow, + doInner func(context.Context) error, +) error { + start := time.Now() + ctx = logging.ToCtx(ctx, m.logger) + ctx = logging.With(ctx, attributesFromJobRow(job)...) + if err := doInner(ctx); err != nil { + logging.WithError(ctx, err).Warn("job processing error") + return err + } + logging.Info(ctx, "job processed successfully", + slog.Duration("duration", time.Since(start)), + ) + return nil +} + +func attributesFromJobRow(j *rivertype.JobRow) []any { + attributes := make([]any, 0, 14) + attributes = append(attributes, + slog.String("queue", j.Queue), + slog.Int64("job_id", j.ID), + slog.String("kind", j.Kind), + slog.Int("priority", j.Priority), + slog.Int("max_attempts", j.MaxAttempts), + slog.String("state", string(j.State)), + slog.String("unique_key", hex.EncodeToString(j.UniqueKey)), + ) + if j.AttemptedAt != nil { + attributes = append(attributes, + slog.Time("created_at", j.CreatedAt), + slog.Int("attempt", j.Attempt), + slog.Time("attempted_at", *j.AttemptedAt), + slog.Any("attempted_by", j.AttemptedBy), + ) + } + if j.FinalizedAt != nil { + attributes = append(attributes, slog.Time("finalized_at", *j.FinalizedAt)) + } + if !j.ScheduledAt.IsZero() { + attributes = append(attributes, slog.Time("scheduled_at", j.ScheduledAt)) + } + if len(j.Tags) > 0 { + attributes = append(attributes, slog.Any("tags", j.Tags)) + } + return attributes +} + +func attributesFromJobInsertResult(j *rivertype.JobInsertResult) []any { + attributes := make([]any, 0, 15) + attributes = append(attributes, attributesFromJobRow(j.Job)...) + attributes = append(attributes, slog.Bool("unique_skipped_as_duplicate", j.UniqueSkippedAsDuplicate)) + return attributes +} diff --git a/internal/queue/queue.go b/internal/queue/queue.go index 8ea831e6b..0566ad4e0 100644 --- a/internal/queue/queue.go +++ b/internal/queue/queue.go @@ -10,9 +10,9 @@ import ( "github.com/riverqueue/river/rivertype" "github.com/riverqueue/rivercontrib/otelriver" "github.com/robfig/cron/v3" - "github.com/zitadel/logging" "go.opentelemetry.io/otel" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/internal/database" ) @@ -31,10 +31,13 @@ type Config struct { } func NewQueue(config *Config) (_ *Queue, err error) { - middleware := []rivertype.Middleware{otelriver.NewMiddleware(&otelriver.MiddlewareConfig{ - MeterProvider: otel.GetMeterProvider(), - DurationUnit: "ms", - })} + middleware := []rivertype.Middleware{ + otelriver.NewMiddleware(&otelriver.MiddlewareConfig{ + MeterProvider: otel.GetMeterProvider(), + DurationUnit: "ms", + }), + newLogMiddleware(), + } return &Queue{ driver: riverdatabasesql.New(config.Client.DB), config: &river.Config{ @@ -67,9 +70,9 @@ func (q *Queue) Start(ctx context.Context) (err error) { return q.client.Start(ctx) } -func (q *Queue) AddWorkers(w ...Worker) { +func (q *Queue) AddWorkers(ctx context.Context, w ...Worker) { if q == nil { - logging.Info("skip adding workers because queue is not set") + logging.Info(ctx, "skip adding workers because queue is not set") return } for _, worker := range w { @@ -77,9 +80,9 @@ func (q *Queue) AddWorkers(w ...Worker) { } } -func (q *Queue) AddPeriodicJob(schedule cron.Schedule, jobArgs river.JobArgs, opts ...InsertOpt) (handle rivertype.PeriodicJobHandle) { +func (q *Queue) AddPeriodicJob(ctx context.Context, schedule cron.Schedule, jobArgs river.JobArgs, opts ...InsertOpt) (handle rivertype.PeriodicJobHandle) { if q == nil { - logging.Info("skip adding periodic job because queue is not set") + logging.Info(ctx, "skip adding periodic job because queue is not set") return } options := new(river.InsertOpts) diff --git a/internal/serviceping/worker.go b/internal/serviceping/worker.go index 445513858..e6c74a558 100644 --- a/internal/serviceping/worker.go +++ b/internal/serviceping/worker.go @@ -229,7 +229,7 @@ func Register( if err != nil { return err } - q.AddWorkers(&Worker{ + q.AddWorkers(ctx, &Worker{ reportClient: NewClient(config), db: queries, queue: q, @@ -240,7 +240,7 @@ func Register( return nil } -func Start(config *Config, q *queue.Queue) error { +func Start(ctx context.Context, config *Config, q *queue.Queue) error { if !config.Enabled { return nil } @@ -249,6 +249,7 @@ func Start(config *Config, q *queue.Queue) error { return err } q.AddPeriodicJob( + ctx, schedule, &ServicePingReport{}, queue.WithQueueName(QueueName), diff --git a/internal/zerrors/already_exists.go b/internal/zerrors/already_exists.go index 11fdef01f..d37c5bc2b 100644 --- a/internal/zerrors/already_exists.go +++ b/internal/zerrors/already_exists.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowAlreadyExists(parent error, id, message string) error { - return newZitadelError(KindAlreadyExists, parent, id, message) + return CreateZitadelError(KindAlreadyExists, parent, id, message, 1) } func ThrowAlreadyExistsf(parent error, id, format string, a ...any) error { - return newZitadelError(KindAlreadyExists, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindAlreadyExists, parent, id, fmt.Sprintf(format, a...), 1) } func IsErrorAlreadyExists(err error) bool { diff --git a/internal/zerrors/deadline_exceeded.go b/internal/zerrors/deadline_exceeded.go index 00fe0fa15..a601fe92b 100644 --- a/internal/zerrors/deadline_exceeded.go +++ b/internal/zerrors/deadline_exceeded.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowDeadlineExceeded(parent error, id, message string) error { - return newZitadelError(KindDeadlineExceeded, parent, id, message) + return CreateZitadelError(KindDeadlineExceeded, parent, id, message, 1) } func ThrowDeadlineExceededf(parent error, id, format string, a ...any) error { - return newZitadelError(KindDeadlineExceeded, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindDeadlineExceeded, parent, id, fmt.Sprintf(format, a...), 1) } func IsDeadlineExceeded(err error) bool { diff --git a/internal/zerrors/internal.go b/internal/zerrors/internal.go index 950633566..bd96399c9 100644 --- a/internal/zerrors/internal.go +++ b/internal/zerrors/internal.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowInternal(parent error, id, message string) error { - return newZitadelError(KindInternal, parent, id, message) + return CreateZitadelError(KindInternal, parent, id, message, 1) } func ThrowInternalf(parent error, id, format string, a ...any) error { - return newZitadelError(KindInternal, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindInternal, parent, id, fmt.Sprintf(format, a...), 1) } func IsInternal(err error) bool { diff --git a/internal/zerrors/invalid_argument.go b/internal/zerrors/invalid_argument.go index fd0df961a..53b31561f 100644 --- a/internal/zerrors/invalid_argument.go +++ b/internal/zerrors/invalid_argument.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowInvalidArgument(parent error, id, message string) error { - return newZitadelError(KindInvalidArgument, parent, id, message) + return CreateZitadelError(KindInvalidArgument, parent, id, message, 1) } func ThrowInvalidArgumentf(parent error, id, format string, a ...any) error { - return newZitadelError(KindInvalidArgument, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindInvalidArgument, parent, id, fmt.Sprintf(format, a...), 1) } func IsErrorInvalidArgument(err error) bool { diff --git a/internal/zerrors/not_found.go b/internal/zerrors/not_found.go index c64d4b415..ae1580458 100644 --- a/internal/zerrors/not_found.go +++ b/internal/zerrors/not_found.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowNotFound(parent error, id, message string) error { - return newZitadelError(KindNotFound, parent, id, message) + return CreateZitadelError(KindNotFound, parent, id, message, 1) } func ThrowNotFoundf(parent error, id, format string, a ...any) error { - return newZitadelError(KindNotFound, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindNotFound, parent, id, fmt.Sprintf(format, a...), 1) } func IsNotFound(err error) bool { diff --git a/internal/zerrors/permission_denied.go b/internal/zerrors/permission_denied.go index 076791f68..3af50adac 100644 --- a/internal/zerrors/permission_denied.go +++ b/internal/zerrors/permission_denied.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowPermissionDenied(parent error, id, message string) error { - return newZitadelError(KindPermissionDenied, parent, id, message) + return CreateZitadelError(KindPermissionDenied, parent, id, message, 1) } func ThrowPermissionDeniedf(parent error, id, format string, a ...any) error { - return newZitadelError(KindPermissionDenied, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindPermissionDenied, parent, id, fmt.Sprintf(format, a...), 1) } func IsPermissionDenied(err error) bool { diff --git a/internal/zerrors/precondition_failed.go b/internal/zerrors/precondition_failed.go index c92b1b56f..e1bcebfb4 100644 --- a/internal/zerrors/precondition_failed.go +++ b/internal/zerrors/precondition_failed.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowPreconditionFailed(parent error, id, message string) error { - return newZitadelError(KindPreconditionFailed, parent, id, message) + return CreateZitadelError(KindPreconditionFailed, parent, id, message, 1) } func ThrowPreconditionFailedf(parent error, id, format string, a ...any) error { - return newZitadelError(KindPreconditionFailed, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindPreconditionFailed, parent, id, fmt.Sprintf(format, a...), 1) } func IsPreconditionFailed(err error) bool { diff --git a/internal/zerrors/resource_exhausted.go b/internal/zerrors/resource_exhausted.go index 63cb000db..52bf6254c 100644 --- a/internal/zerrors/resource_exhausted.go +++ b/internal/zerrors/resource_exhausted.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowResourceExhausted(parent error, id, message string) error { - return newZitadelError(KindResourceExhausted, parent, id, message) + return CreateZitadelError(KindResourceExhausted, parent, id, message, 1) } func ThrowResourceExhaustedf(parent error, id, format string, a ...any) error { - return newZitadelError(KindResourceExhausted, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindResourceExhausted, parent, id, fmt.Sprintf(format, a...), 1) } func IsResourceExhausted(err error) bool { diff --git a/internal/zerrors/unauthenticated.go b/internal/zerrors/unauthenticated.go index 13f1ec317..6948c1e21 100644 --- a/internal/zerrors/unauthenticated.go +++ b/internal/zerrors/unauthenticated.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowUnauthenticated(parent error, id, message string) error { - return newZitadelError(KindUnauthenticated, parent, id, message) + return CreateZitadelError(KindUnauthenticated, parent, id, message, 1) } func ThrowUnauthenticatedf(parent error, id, format string, a ...any) error { - return newZitadelError(KindUnauthenticated, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindUnauthenticated, parent, id, fmt.Sprintf(format, a...), 1) } func IsUnauthenticated(err error) bool { diff --git a/internal/zerrors/unavailable.go b/internal/zerrors/unavailable.go index 2b5c1cff0..41785a81f 100644 --- a/internal/zerrors/unavailable.go +++ b/internal/zerrors/unavailable.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowUnavailable(parent error, id, message string) error { - return newZitadelError(KindUnavailable, parent, id, message) + return CreateZitadelError(KindUnavailable, parent, id, message, 1) } func ThrowUnavailablef(parent error, id, format string, a ...any) error { - return newZitadelError(KindUnavailable, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindUnavailable, parent, id, fmt.Sprintf(format, a...), 1) } func IsUnavailable(err error) bool { diff --git a/internal/zerrors/unimplemented.go b/internal/zerrors/unimplemented.go index 790a86391..d1f7f3a64 100644 --- a/internal/zerrors/unimplemented.go +++ b/internal/zerrors/unimplemented.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowUnimplemented(parent error, id, message string) error { - return newZitadelError(KindUnimplemented, parent, id, message) + return CreateZitadelError(KindUnimplemented, parent, id, message, 1) } func ThrowUnimplementedf(parent error, id, format string, a ...any) error { - return newZitadelError(KindUnimplemented, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindUnimplemented, parent, id, fmt.Sprintf(format, a...), 1) } func IsUnimplemented(err error) bool { diff --git a/internal/zerrors/unknown.go b/internal/zerrors/unknown.go index 63d114153..2e2a1bf5b 100644 --- a/internal/zerrors/unknown.go +++ b/internal/zerrors/unknown.go @@ -3,11 +3,11 @@ package zerrors import "fmt" func ThrowUnknown(parent error, id, message string) error { - return newZitadelError(KindUnknown, parent, id, message) + return CreateZitadelError(KindUnknown, parent, id, message, 1) } func ThrowUnknownf(parent error, id, format string, a ...any) error { - return newZitadelError(KindUnknown, parent, id, fmt.Sprintf(format, a...)) + return CreateZitadelError(KindUnknown, parent, id, fmt.Sprintf(format, a...), 1) } func IsUnknown(err error) bool { diff --git a/internal/zerrors/zerror.go b/internal/zerrors/zerror.go index 19b9cba3e..bb3b6ba58 100644 --- a/internal/zerrors/zerror.go +++ b/internal/zerrors/zerror.go @@ -117,23 +117,34 @@ type ZitadelError struct { } func ThrowError(parent error, id, message string) error { - return newZitadelError(KindUnknown, parent, id, message) + return CreateZitadelError(KindUnknown, parent, id, message, 1) } -func CreateZitadelError(kind Kind, parent error, id, message string) *ZitadelError { - return newZitadelError(kind, parent, id, message) -} - -func newZitadelError(kind Kind, parent error, id, message string) *ZitadelError { +// CreateZitadelError creates a ZitadelError of the given kind. +// If ReportLocation or StackTrace are enabled, they are added to the error. +// The skip parameter defines how many stack frames to skip when determining +// the report location. +// A skip value of 0 means the location where CreateZitadelError is called. +// When the parent error is also a ZitadelError, the report location and stack trace +// are inherited from the parent error. +func CreateZitadelError(kind Kind, parent error, id, message string, skip int) *ZitadelError { err := &ZitadelError{ Kind: kind, Parent: parent, ID: id, Message: message, } + var target *ZitadelError + if errors.As(parent, &target) { + // inherit stack trace and report location from parent error + err.reportLocation = target.reportLocation + err.stackTrace = target.stackTrace + err.hasStackTrace = target.hasStackTrace + return err + } + if enableReportLocation.Load() { - // skip 2: newZitadelError + Create / Throw function. - err.reportLocation = sloggcp.NewReportLocation(2) + err.reportLocation = sloggcp.NewReportLocation(skip + 1) } if enableStackTrace.Load() { err.stackTrace = debug.Stack() diff --git a/internal/zerrors/zerror_test.go b/internal/zerrors/zerror_test.go index 8ea50cd64..670d4faaa 100644 --- a/internal/zerrors/zerror_test.go +++ b/internal/zerrors/zerror_test.go @@ -19,7 +19,7 @@ func TestErrorMethod(t *testing.T) { func TestZitadelError_Is(t *testing.T) { parent := errors.New("parent error") - target := newZitadelError(KindAborted, parent, "id", "message") + target := CreateZitadelError(KindAborted, parent, "id", "message", 0) tests := []struct { name string // description of this test case err error @@ -32,27 +32,27 @@ func TestZitadelError_Is(t *testing.T) { }, { name: "different kind", - err: newZitadelError(KindNotFound, parent, "id", "message"), + err: CreateZitadelError(KindNotFound, parent, "id", "message", 0), want: false, }, { name: "different id", - err: newZitadelError(KindAborted, parent, "otherID", "message"), + err: CreateZitadelError(KindAborted, parent, "otherID", "message", 0), want: false, }, { name: "different message", - err: newZitadelError(KindAborted, parent, "id", "other message"), + err: CreateZitadelError(KindAborted, parent, "id", "other message", 0), want: false, }, { name: "different parent", - err: newZitadelError(KindAborted, errors.New("other parent"), "id", "message"), + err: CreateZitadelError(KindAborted, errors.New("other parent"), "id", "message", 0), want: false, }, { name: "same error", - err: newZitadelError(KindAborted, parent, "id", "message"), + err: CreateZitadelError(KindAborted, parent, "id", "message", 0), want: true, }, } diff --git a/main.go b/main.go index 06b10bd86..f49a17d84 100644 --- a/main.go +++ b/main.go @@ -1,15 +1,18 @@ package main import ( + "context" "os" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" "github.com/zitadel/zitadel/cmd" ) func main() { args := os.Args[1:] rootCmd := cmd.New(os.Stdout, os.Stdin, args, nil) - if err := rootCmd.Execute(); err != nil { + ctx := logging.NewCtx(context.Background(), logging.StreamRuntime) + if err := rootCmd.ExecuteContext(ctx); err != nil { // error is logged by the command itself os.Exit(1) }