From 11dbb1b2772640cd76f5bdb893b8d1e6d8a21379 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tim=20M=C3=B6hlmann?= Date: Wed, 4 Feb 2026 11:51:43 +0100 Subject: [PATCH] feat(logging): add streams (#11435) # Which Problems Are Solved Streams allow differentiating logs produced by different components of Zitadel. # How the Problems Are Solved The `backend/v3/instrumentation/logging` package now exposes convenience function for setting and getting a logger from the context. As well as high-level functions to emit log records at various levels. When constructing a new logger a "stream" needs to be specified: - **runtime**: General runtime logs, such as startup and shutdown messages. Default for logs that do not belong to the other categories. - **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. Disabled by default, contains sensitive information. Each line from the returned logger contains a `stream` field as well as a `version` field with the current Zitadel version. ## Runtime config Streams can be enabled by passing an array of stream names in the runtime config. Because some log streams may contain sensitive data (especially events), it is now also possible to mask values by their key. # Additional Changes - Wrap `slogctx` in the `logging` package. (Except API error converter packages, because of import cycle) - Add some docs to `logging` package so other devs understand how to add logging to Zitadel - Add `logging.OnError` and `logging.WithError` helper functions with `Panic()` and `Fatal()` methods, to preserve current calls in the `cmd` packages. - Add instance context extractor. - Only output request details in the request info log. Request ID remains propagated through context. - Moved middleware functionality into protocol specific packages. - Removed setting of URI to context in metric middleware. There were ony setters and no getters. (Unused value) - Reuse a single statusWriter in the middleware package for middlewares that need to know the response status. # Additional Context - Closes #11333 - Closes #11331 - Partly #11330 --------- Co-authored-by: Silvan <27845747+adlerhurst@users.noreply.github.com> --- backend/v3/domain/invoker_logging.go | 4 +- backend/v3/instrumentation/instrumentation.go | 6 - .../v3/instrumentation/logformat_enumer.go | 8 +- .../logging/connect_handler.go | 34 - .../instrumentation/logging/grpc_handler.go | 36 -- .../instrumentation/logging/http_handler.go | 45 -- backend/v3/instrumentation/logging/logging.go | 221 +++++++ .../instrumentation/logging/logging_test.go | 583 ++++++++++++++++++ .../instrumentation/metrics/http_handler.go | 97 +-- backend/v3/instrumentation/slog.go | 218 ++++--- backend/v3/instrumentation/slog_test.go | 138 +++++ backend/v3/instrumentation/stream.go | 29 + backend/v3/instrumentation/stream_enumer.go | 106 ++++ backend/v3/instrumentation/stream_test.go | 13 + backend/v3/instrumentation/tracing.go | 16 +- .../instrumentation/tracing/http_handler.go | 23 - .../database/events_testing/events_test.go | 4 +- cmd/build/info.go | 7 +- cmd/defaults.yaml | 30 +- cmd/initialise/config.go | 40 +- cmd/initialise/init.go | 18 +- cmd/initialise/verify_database.go | 23 +- cmd/initialise/verify_grant.go | 23 +- cmd/initialise/verify_user.go | 24 +- cmd/initialise/verify_zitadel.go | 37 +- cmd/mirror/auth.go | 25 +- cmd/mirror/config.go | 63 +- cmd/mirror/defaults.yaml | 34 +- cmd/mirror/event_store.go | 72 ++- cmd/mirror/mirror.go | 29 +- cmd/mirror/projections.go | 93 +-- cmd/mirror/system.go | 35 +- cmd/mirror/verify.go | 23 +- cmd/ready/config.go | 36 +- cmd/ready/ready.go | 32 +- cmd/setup/10.go | 25 +- cmd/setup/14.go | 4 +- cmd/setup/15.go | 5 +- cmd/setup/16.go | 5 +- cmd/setup/35.go | 5 +- cmd/setup/36.go | 11 +- cmd/setup/39.go | 5 +- cmd/setup/40.go | 7 +- cmd/setup/43.go | 5 +- cmd/setup/44.go | 5 +- cmd/setup/45.go | 7 +- cmd/setup/46.go | 5 +- cmd/setup/49.go | 5 +- cmd/setup/53.go | 5 +- cmd/setup/58.go | 5 +- cmd/setup/59.go | 5 +- cmd/setup/cleanup.go | 38 +- cmd/setup/config.go | 28 +- cmd/setup/config_test.go | 6 +- cmd/setup/setup.go | 76 +-- cmd/setup/steps.yaml | 76 ++- cmd/setup/sync_role_permissions.go | 12 +- cmd/start/config.go | 17 +- cmd/start/flags.go | 3 +- cmd/start/start.go | 16 +- cmd/start/start_from_init.go | 48 +- cmd/start/start_from_setup.go | 23 +- cmd/zitadel.go | 7 +- go.mod | 6 +- go.sum | 13 +- internal/api/authz/instance.go | 4 +- internal/api/grpc/gerrors/zitadel_errors.go | 11 +- .../connect_middleware/log_interceptor.go | 46 +- internal/api/grpc/server/gateway.go | 1 - .../grpc/server/middleware/log_interceptor.go | 48 +- internal/api/http/error.go | 5 +- .../api/http/middleware/access_interceptor.go | 18 +- .../api/http/middleware/log_interceptor.go | 30 +- .../http/middleware/metrics_interceptor.go | 48 +- internal/api/http/middleware/middleware.go | 29 + .../api/http/middleware/middleware_test.go | 38 ++ .../api/http/middleware/trace_interceptor.go | 17 +- .../api/ui/login/external_provider_handler.go | 2 +- internal/eventstore/event.go | 58 ++ internal/eventstore/event_test.go | 139 +++++ internal/eventstore/eventstore.go | 28 +- .../eventstore/handler/v2/failed_event.go | 18 +- .../eventstore/handler/v2/field_handler.go | 14 +- internal/eventstore/handler/v2/handler.go | 64 +- internal/eventstore/handler/v2/init.go | 11 +- internal/eventstore/handler/v2/log.go | 23 - internal/eventstore/handler/v2/metrics.go | 20 +- .../eventstore/handler/v2/metrics_test.go | 10 +- internal/eventstore/handler/v2/state.go | 15 +- internal/eventstore/handler/v2/state_test.go | 2 +- internal/eventstore/handler/v2/statement.go | 12 +- internal/execution/projections.go | 3 +- internal/migration/migration.go | 15 +- internal/notification/projections.go | 4 +- internal/queue/log.go | 106 ++++ internal/queue/queue.go | 21 +- internal/serviceping/worker.go | 5 +- internal/zerrors/already_exists.go | 4 +- internal/zerrors/deadline_exceeded.go | 4 +- internal/zerrors/internal.go | 4 +- internal/zerrors/invalid_argument.go | 4 +- internal/zerrors/not_found.go | 4 +- internal/zerrors/permission_denied.go | 4 +- internal/zerrors/precondition_failed.go | 4 +- internal/zerrors/resource_exhausted.go | 4 +- internal/zerrors/unauthenticated.go | 4 +- internal/zerrors/unavailable.go | 4 +- internal/zerrors/unimplemented.go | 4 +- internal/zerrors/unknown.go | 4 +- internal/zerrors/zerror.go | 27 +- internal/zerrors/zerror_test.go | 12 +- main.go | 5 +- 112 files changed, 2679 insertions(+), 981 deletions(-) delete mode 100644 backend/v3/instrumentation/logging/connect_handler.go delete mode 100644 backend/v3/instrumentation/logging/grpc_handler.go delete mode 100644 backend/v3/instrumentation/logging/http_handler.go create mode 100644 backend/v3/instrumentation/logging/logging.go create mode 100644 backend/v3/instrumentation/logging/logging_test.go create mode 100644 backend/v3/instrumentation/slog_test.go create mode 100644 backend/v3/instrumentation/stream.go create mode 100644 backend/v3/instrumentation/stream_enumer.go create mode 100644 backend/v3/instrumentation/stream_test.go delete mode 100644 backend/v3/instrumentation/tracing/http_handler.go create mode 100644 internal/api/http/middleware/middleware.go create mode 100644 internal/eventstore/event_test.go delete mode 100644 internal/eventstore/handler/v2/log.go create mode 100644 internal/queue/log.go 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) }