diff --git a/example/main.txt b/examples/main.txt similarity index 100% rename from example/main.txt rename to examples/main.txt diff --git a/examples/simple-log/log.go b/examples/simple-log/log.go new file mode 100644 index 0000000..0e4ef68 --- /dev/null +++ b/examples/simple-log/log.go @@ -0,0 +1,38 @@ +package main + +import ( + "context" + "errors" + + errutil "github.com/NYCU-SDC/summer/pkg/error" + logutil "github.com/NYCU-SDC/summer/pkg/log" + "go.uber.org/zap" +) + +func main() { + logger := zap.NewExample() + + ctx, eventLogger := logutil.SetupFlow( + context.Background(), + logger, + "user.create", + zap.String("request.id", "req-7"), + zap.String("enduser.id", "user-42"), + zap.String("service.name", "account-api"), + ) + eventLogger = logutil.WithEventOutcome(logutil.EventOutcomeFailure, eventLogger) + + ctx = logutil.WithErrorType(ctx, errutil.ALREADY_EXISTS) + ctx = logutil.WithReason(ctx, "duplicate_email") + + baseErr := errors.New("email already exists") + + // Wrap the error when it needs to carry detail to the logging layer. + err := errutil.WrapInfoError(baseErr, map[errutil.ErrorInfoKey]any{ + errutil.ErrorInfoOperation: "create_user", + errutil.ErrorInfoField: "email", + errutil.ErrorInfoRetryable: false, + }) + + logutil.Error(ctx, eventLogger, "create user rejected", err, zap.String("email.domain", "example.com")) +} diff --git a/pkg/database/errors.go b/pkg/database/errors.go index 69e32ad..36ab683 100644 --- a/pkg/database/errors.go +++ b/pkg/database/errors.go @@ -31,6 +31,12 @@ func (e InternalServerError) Error() string { return fmt.Sprintf("internal server error: %s", e.Source.Error()) } +func (e InternalServerError) Unwrap() error { + return e.Source +} + +// WrapDBError is the legacy helper: it logs the error and classifies it into a domain error. +// New code should return domain errors directly and log through pkg/log. func WrapDBError(err error, logger *zap.Logger, operation string) error { if err == nil { return nil @@ -42,19 +48,19 @@ func WrapDBError(err error, logger *zap.Logger, operation string) error { switch { case errors.Is(err, pgx.ErrNoRows): - wrappedErr = fmt.Errorf("%w: %v", errorPkg.ErrNotFound, err) + wrappedErr = fmt.Errorf("%w: %w", errorPkg.ErrNotFound, err) case errors.Is(err, context.DeadlineExceeded): - wrappedErr = fmt.Errorf("%w: %v", ErrQueryTimeout, err) + wrappedErr = fmt.Errorf("%w: %w", ErrQueryTimeout, err) default: var pgErr *pgconn.PgError if errors.As(err, &pgErr) { switch pgErr.Code { case PGErrUniqueViolation: - wrappedErr = fmt.Errorf("%w: %v", ErrUniqueViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrUniqueViolation, err) case PGErrForeignKeyViolation: - wrappedErr = fmt.Errorf("%w: %v", ErrForeignKeyViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrForeignKeyViolation, err) case PGErrDeadlockDetected: - wrappedErr = fmt.Errorf("%w: %v", ErrDeadlockDetected, err) + wrappedErr = fmt.Errorf("%w: %w", ErrDeadlockDetected, err) } } } @@ -70,6 +76,9 @@ func WrapDBError(err error, logger *zap.Logger, operation string) error { return wrappedErr } +// WrapDBErrorWithKeyValue is the legacy helper: it logs the error and classifies it into a domain error, +// using table/key/value to build the not-found error. New code should return domain errors directly +// and log through pkg/log. func WrapDBErrorWithKeyValue(err error, table, key, value string, logger *zap.Logger, operation string) error { if err == nil { return nil @@ -83,17 +92,17 @@ func WrapDBErrorWithKeyValue(err error, table, key, value string, logger *zap.Lo case errors.Is(err, pgx.ErrNoRows): wrappedErr = errorPkg.NewNotFoundError(table, key, value, "") case errors.Is(err, context.DeadlineExceeded): - wrappedErr = fmt.Errorf("%w: %v", ErrQueryTimeout, err) + wrappedErr = fmt.Errorf("%w: %w", ErrQueryTimeout, err) default: var pgErr *pgconn.PgError if errors.As(err, &pgErr) { switch pgErr.Code { case PGErrUniqueViolation: - wrappedErr = fmt.Errorf("%w: %v", ErrUniqueViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrUniqueViolation, err) case PGErrForeignKeyViolation: - wrappedErr = fmt.Errorf("%w: %v", ErrForeignKeyViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrForeignKeyViolation, err) case PGErrDeadlockDetected: - wrappedErr = fmt.Errorf("%w: %v", ErrDeadlockDetected, err) + wrappedErr = fmt.Errorf("%w: %w", ErrDeadlockDetected, err) } } } diff --git a/pkg/database/errors_mssql.go b/pkg/database/errors_mssql.go index 0e92a4d..8a3769e 100644 --- a/pkg/database/errors_mssql.go +++ b/pkg/database/errors_mssql.go @@ -19,6 +19,8 @@ const ( MSSQLErrDeadlockDetected = 1205 // Deadlock detected ) +// WrapMSSQLError is the legacy helper: it logs the error and classifies it into a domain error. +// New code should return domain errors directly and log through pkg/log. func WrapMSSQLError(err error, logger *zap.Logger, operation string) error { if err == nil { return nil @@ -30,19 +32,19 @@ func WrapMSSQLError(err error, logger *zap.Logger, operation string) error { switch { case errors.Is(err, sql.ErrNoRows): - wrappedErr = fmt.Errorf("%w: %v", errorPkg.ErrNotFound, err) + wrappedErr = fmt.Errorf("%w: %w", errorPkg.ErrNotFound, err) case errors.Is(err, context.DeadlineExceeded): - wrappedErr = fmt.Errorf("%w: %v", ErrQueryTimeout, err) + wrappedErr = fmt.Errorf("%w: %w", ErrQueryTimeout, err) default: var mssqlErr mssql.Error if errors.As(err, &mssqlErr) { switch mssqlErr.Number { case MSSQLErrUniqueViolation, MSSQLErrUniqueIndex: - wrappedErr = fmt.Errorf("%w: %v", ErrUniqueViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrUniqueViolation, err) case MSSQLErrForeignKeyViolation: - wrappedErr = fmt.Errorf("%w: %v", ErrForeignKeyViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrForeignKeyViolation, err) case MSSQLErrDeadlockDetected: - wrappedErr = fmt.Errorf("%w: %v", ErrDeadlockDetected, err) + wrappedErr = fmt.Errorf("%w: %w", ErrDeadlockDetected, err) } } } @@ -58,6 +60,9 @@ func WrapMSSQLError(err error, logger *zap.Logger, operation string) error { return wrappedErr } +// WrapMSSQLErrorWithKeyValue is the legacy helper: it logs the error and classifies it into a domain error, +// using table/key/value to build the not-found error. New code should return domain errors directly +// and log through pkg/log. func WrapMSSQLErrorWithKeyValue(err error, table, key, value string, logger *zap.Logger, operation string) error { if err == nil { return nil @@ -71,17 +76,17 @@ func WrapMSSQLErrorWithKeyValue(err error, table, key, value string, logger *zap case errors.Is(err, sql.ErrNoRows): wrappedErr = errorPkg.NewNotFoundError(table, key, value, "") case errors.Is(err, context.DeadlineExceeded): - wrappedErr = fmt.Errorf("%w: %v", ErrQueryTimeout, err) + wrappedErr = fmt.Errorf("%w: %w", ErrQueryTimeout, err) default: var mssqlErr mssql.Error if errors.As(err, &mssqlErr) { switch mssqlErr.Number { case MSSQLErrUniqueViolation, MSSQLErrUniqueIndex: - wrappedErr = fmt.Errorf("%w: %v", ErrUniqueViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrUniqueViolation, err) case MSSQLErrForeignKeyViolation: - wrappedErr = fmt.Errorf("%w: %v", ErrForeignKeyViolation, err) + wrappedErr = fmt.Errorf("%w: %w", ErrForeignKeyViolation, err) case MSSQLErrDeadlockDetected: - wrappedErr = fmt.Errorf("%w: %v", ErrDeadlockDetected, err) + wrappedErr = fmt.Errorf("%w: %w", ErrDeadlockDetected, err) } } } diff --git a/pkg/error/error_warp.go b/pkg/error/error_warp.go new file mode 100644 index 0000000..5703d38 --- /dev/null +++ b/pkg/error/error_warp.go @@ -0,0 +1,299 @@ +package errutil + +import ( + "errors" + "runtime/debug" + + "go.uber.org/zap" +) + +// ErrorType is a stable machine-readable error classification for logs. +// +// The values mirror canonical status-like categories so services can group +// unrelated Go error types under the same operational meaning. +type ErrorType string + +const ( + // OK indicates that no error occurred. + OK ErrorType = "OK" + // CANCELLED indicates that an operation was cancelled before completion. + CANCELLED ErrorType = "CANCELLED" + // UNKNOWN indicates that the error category could not be determined. + UNKNOWN ErrorType = "UNKNOWN" + // INVALID_ARGUMENT indicates that the caller supplied invalid input. + INVALID_ARGUMENT ErrorType = "INVALID_ARGUMENT" + // DEADLINE_EXCEEDED indicates that an operation exceeded its time limit. + DEADLINE_EXCEEDED ErrorType = "DEADLINE_EXCEEDED" + // NOT_FOUND indicates that a requested resource does not exist. + NOT_FOUND ErrorType = "NOT_FOUND" + // ALREADY_EXISTS indicates that a resource already exists. + ALREADY_EXISTS ErrorType = "ALREADY_EXISTS" + // PERMISSION_DENIED indicates that the caller lacks permission. + PERMISSION_DENIED ErrorType = "PERMISSION_DENIED" + // UNAUTHENTICATED indicates that authentication is required or invalid. + UNAUTHENTICATED ErrorType = "UNAUTHENTICATED" + // RESOURCE_EXHAUSTED indicates that quota, capacity, or another limit was exhausted. + RESOURCE_EXHAUSTED ErrorType = "RESOURCE_EXHAUSTED" + // FAILED_PRECONDITION indicates that the system state does not allow the operation. + FAILED_PRECONDITION ErrorType = "FAILED_PRECONDITION" + // ABORTED indicates that an operation was aborted, often due to a conflict. + ABORTED ErrorType = "ABORTED" + // OUT_OF_RANGE indicates that an input is outside the allowed range. + OUT_OF_RANGE ErrorType = "OUT_OF_RANGE" + // UNIMPLEMENTED indicates that the requested operation is not implemented. + UNIMPLEMENTED ErrorType = "UNIMPLEMENTED" + // INTERNAL indicates an unexpected server-side failure. + INTERNAL ErrorType = "INTERNAL" + // UNAVAILABLE indicates that a dependency or service is temporarily unavailable. + UNAVAILABLE ErrorType = "UNAVAILABLE" + // DATA_LOSS indicates unrecoverable data corruption or loss. + DATA_LOSS ErrorType = "DATA_LOSS" +) + +// ErrorInfoKey defines common keys for structured metadata carried by errors. +// +// These keys are intended for InfoError maps and become error.info. fields +// when emitted by ErrorFields or ErrorFieldsWithStacktrace. +type ErrorInfoKey string + +const ( + // ErrorInfoReason describes why an error occurred or a branch was taken. + ErrorInfoReason ErrorInfoKey = "reason" + // ErrorInfoOperation names the operation that produced the error. + ErrorInfoOperation ErrorInfoKey = "operation" + // ErrorInfoRetryable records whether retrying the operation may succeed. + ErrorInfoRetryable ErrorInfoKey = "retryable" + // ErrorInfoField names the input or domain field related to the error. + ErrorInfoField ErrorInfoKey = "field" + // ErrorInfoUserID records the user ID related to the error. + ErrorInfoUserID ErrorInfoKey = "user.id" + // ErrorInfoRequestID records the request ID related to the error. + ErrorInfoRequestID ErrorInfoKey = "request.id" +) + +// InfoCarrier marks an error as carrying structured log metadata. +// +// ErrorFields and InfoFieldsFromError use errors.As to find this interface in +// an error chain and emit each returned key/value pair as log fields. +type InfoCarrier interface { + LogInfo() map[string]any +} + +// ErrorTypeCarrier marks an error as carrying a stable error.type value. +// +// ErrorFields uses errors.As to find this interface in an error chain and emit +// the returned value as error.type. +type ErrorTypeCarrier interface { + LogErrorType() ErrorType +} + +// InfoError is an error wrapper that carries structured logging metadata. +// +// It preserves Base for errors.Is/errors.As through Unwrap, optionally carries +// a canonical ErrorType, and exposes Info as string-keyed log metadata through +// LogInfo. Use it only when an error must carry observability metadata across an +// API boundary; do not use it as a general domain error wrapping policy. +type InfoError[K ~string, V any] struct { + Base error + Type ErrorType + Info map[K]V +} + +// Error returns the base error message, falling back to Type when Base is nil. +func (e *InfoError[K, V]) Error() string { + if e == nil { + return "" + } + + if e.Base != nil { + return e.Base.Error() + } + + if e.Type != "" { + return string(e.Type) + } + + return "" +} + +// Unwrap returns the wrapped base error for errors.Is and errors.As. +func (e *InfoError[K, V]) Unwrap() error { + if e == nil { + return nil + } + + return e.Base +} + +// LogInfo returns Info with string keys for structured logging. +// +// A new map is allocated so callers cannot mutate the original Info map through +// the returned value. +func (e *InfoError[K, V]) LogInfo() map[string]any { + if e == nil || len(e.Info) == 0 { + return nil + } + + out := make(map[string]any, len(e.Info)) + for k, v := range e.Info { + out[string(k)] = v + } + + return out +} + +// LogErrorType returns the canonical error type associated with the error. +func (e *InfoError[K, V]) LogErrorType() ErrorType { + if e == nil { + return "" + } + + return e.Type +} + +// NewInfoError returns an error carrying structured logging metadata. +// +// The returned error wraps base and exposes info through InfoCarrier. This +// constructor does not set error.type; use NewTypedInfoError when a stable error +// category is available. +func NewInfoError[K ~string, V any](base error, info map[K]V) error { + return &InfoError[K, V]{ + Base: base, + Info: info, + } +} + +// WrapInfoError returns an error carrying structured logging metadata. +// +// It is a compatibility alias for NewInfoError. Prefer NewInfoError for new code +// when the intent is to create an error that carries log metadata. +func WrapInfoError[K ~string, V any](base error, info map[K]V) error { + return &InfoError[K, V]{ + Base: base, + Info: info, + } +} + +// NewTypedInfoError returns an error carrying error.type and structured metadata. +// +// The returned error wraps base, exposes errorType through ErrorTypeCarrier, and +// exposes info through InfoCarrier. +func NewTypedInfoError[K ~string, V any](errorType ErrorType, base error, info map[K]V) error { + return &InfoError[K, V]{ + Base: base, + Type: errorType, + Info: info, + } +} + +// WrapTypedInfoError returns an error carrying error.type and structured metadata. +// +// It is a compatibility alias for NewTypedInfoError. Prefer NewTypedInfoError +// for new code when the intent is to create an error that carries log metadata. +func WrapTypedInfoError[K ~string, V any](errorType ErrorType, base error, info map[K]V) error { + return &InfoError[K, V]{ + Base: base, + Type: errorType, + Info: info, + } +} + +// InfoFromError extracts structured logging metadata from err. +// +// It returns nil when err is nil or no InfoCarrier is found in the error chain. +func InfoFromError(err error) map[string]any { + if err == nil { + return nil + } + + var carrier InfoCarrier + if errors.As(err, &carrier) { + return carrier.LogInfo() + } + + return nil +} + +// ErrorTypeFromError extracts a stable error type from err. +// +// It returns an empty ErrorType when err is nil or no ErrorTypeCarrier is found +// in the error chain. +func ErrorTypeFromError(err error) ErrorType { + if err == nil { + return "" + } + + var carrier ErrorTypeCarrier + if errors.As(err, &carrier) { + return carrier.LogErrorType() + } + + return "" +} + +// ErrorFields converts err into standard zap fields for structured error logs. +// +// The returned fields include zap.Error, error.message, exception.message, +// exception.type, optional error.type, and optional error.info.* fields. +// Stacktrace is intentionally excluded; use ErrorFieldsWithStacktrace when the +// call site needs a stacktrace. +func ErrorFields(err error) []zap.Field { + if err == nil { + return nil + } + + fields := []zap.Field{ + zap.Error(err), + zap.String("error.message", err.Error()), + } + + if errorType := ErrorTypeFromError(err); errorType != "" { + fields = append(fields, zap.String("error.type", string(errorType))) + } + + fields = append(fields, InfoFieldsFromError("error.info", err)...) + + return fields +} + +// ErrorFieldsWithStacktrace converts err into zap fields including a stacktrace. +// +// It includes all fields from ErrorFields and adds exception.stacktrace captured +// at the point this function is called. +func ErrorFieldsWithStacktrace(err error) []zap.Field { + if err == nil { + return nil + } + + fields := ErrorFields(err) + fields = append(fields, zap.String("exception.stacktrace", string(debug.Stack()))) + + return fields +} + +// InfoFieldsFromError converts InfoCarrier metadata into namespaced zap fields. +// +// If prefix is empty, fields are emitted under error.info. For example, an info +// key "operation" with the default prefix becomes error.info.operation. +func InfoFieldsFromError(prefix string, err error) []zap.Field { + info := InfoFromError(err) + if len(info) == 0 { + return nil + } + + // TODO: should we keep the prefix here? + if prefix == "" { + prefix = "error.info" + } + + fields := make([]zap.Field, 0, len(info)) + for key, value := range info { + if key == "" { + continue + } + + fields = append(fields, zap.Any(prefix+"."+key, value)) + } + + return fields +} diff --git a/pkg/log/constant.go b/pkg/log/constant.go new file mode 100644 index 0000000..f7bdca1 --- /dev/null +++ b/pkg/log/constant.go @@ -0,0 +1,20 @@ +package logutil + +// EventOutcome describes the result of a logged event. +// +// Use it with WithEventOutcome when the event result fits one of the standard +// outcome values. Use WithOutcome only when a custom outcome string is needed. +type EventOutcome string + +const ( + // EventOutcomeSuccess indicates that an event completed successfully. + EventOutcomeSuccess EventOutcome = "success" + // EventOutcomeFailure indicates that an event failed. + EventOutcomeFailure EventOutcome = "failure" + // EventOutcomeCancelled indicates that an event was cancelled. + EventOutcomeCancelled EventOutcome = "cancelled" + // EventOutcomeTimeout indicates that an event timed out. + EventOutcomeTimeout EventOutcome = "timeout" + // EventOutcomeUnknown indicates that the event result is not known. + EventOutcomeUnknown EventOutcome = "unknown" +) diff --git a/pkg/log/deprecated.go b/pkg/log/deprecated.go new file mode 100644 index 0000000..9156c1e --- /dev/null +++ b/pkg/log/deprecated.go @@ -0,0 +1,48 @@ +package logutil + +import ( + "context" + + "go.opentelemetry.io/otel/trace" + "go.uber.org/zap" +) + +// WithContext returns logger enriched with legacy context fields. +// +// It reads OpenTelemetry trace/span IDs from ctx and also reads the old string +// context keys "user_id", "username", and "name". Those user fields are emitted +// as user_id, username, and display-name for compatibility with older callers. +// +// This is the legacy path. New code should use Constructs for the standard +// context-first logging path, or WithTraceContext and WithUserContext directly +// when decorating a logger, and write user and request values with WithUserID, +// WithUsername, WithDisplayName, and WithRequestID instead of raw string +// context keys. +func WithContext(ctx context.Context, logger *zap.Logger) *zap.Logger { + if ctx == nil { + return logger + } + + spanCtx := trace.SpanFromContext(ctx).SpanContext() + if spanCtx.HasTraceID() { + logger = logger.With(zap.String("trace_id", spanCtx.TraceID().String())) + } + + if spanCtx.HasSpanID() { + logger = logger.With(zap.String("span_id", spanCtx.SpanID().String())) + } + + if ctx.Value("user_id") != nil { + logger = logger.With(zap.Any("user_id", ctx.Value("user_id"))) + } + + if ctx.Value("username") != nil { + logger = logger.With(zap.Any("username", ctx.Value("username"))) + } + + if ctx.Value("name") != nil { + logger = logger.With(zap.Any("display-name", ctx.Value("name"))) + } + + return logger +} diff --git a/pkg/log/doc.go b/pkg/log/doc.go new file mode 100644 index 0000000..a169adb --- /dev/null +++ b/pkg/log/doc.go @@ -0,0 +1,17 @@ +// Package logutil provides the project's structured logging helpers on top of zap. +// +// The package intentionally supports two usage paths. +// +// Context-first logging stores request-scoped fields in context.Context with +// helpers such as SetupFlow, WithFields, WithUserID, WithRequestID, WithReason, +// and WithErrorType. The level helpers such as Info and Error then call +// Constructs to inject those fields, active OpenTelemetry trace fields, user +// fields, request fields, and source code location fields into the log entry. +// +// Logger-first logging decorates an existing *zap.Logger directly with helpers +// such as WithEventName and WithEventOutcome. Use this path when a logger +// already represents a specific event. +// +// The companion pkg/error package provides helpers for errors that carry +// structured detail to the place where they are logged. +package logutil diff --git a/pkg/log/flow.go b/pkg/log/flow.go new file mode 100644 index 0000000..95e6fda --- /dev/null +++ b/pkg/log/flow.go @@ -0,0 +1,30 @@ +package logutil + +import ( + "context" + + "go.uber.org/zap" +) + +// SetupFlow initializes the context and logger fields used by a service flow. +// +// It stores request-scoped fields on ctx, decorates logger with event.name, and +// returns both values for subsequent logutil level calls. A nil ctx becomes +// context.Background, and a nil logger becomes zap.NewNop. +func SetupFlow(ctx context.Context, logger *zap.Logger, eventName string, fields ...zap.Field) (context.Context, *zap.Logger) { + if ctx == nil { + ctx = context.Background() + } + + if logger == nil { + logger = zap.NewNop() + } + + if len(fields) > 0 { + ctx = WithFields(ctx, fields...) + } + + logger = WithEventName(eventName, logger) + + return ctx, logger +} diff --git a/pkg/log/flow_test.go b/pkg/log/flow_test.go new file mode 100644 index 0000000..35f06ac --- /dev/null +++ b/pkg/log/flow_test.go @@ -0,0 +1,80 @@ +package logutil + +import ( + "context" + "testing" + + errutil "github.com/NYCU-SDC/summer/pkg/error" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +// nilContext is passed where a test deliberately exercises the nil-context +// fallback in SetupFlow. Using a variable keeps staticcheck's SA1012 (do not +// pass a nil Context) from firing on an intentional case. +var nilContext context.Context + +func TestSetupFlowInitializesContextAndLogger(t *testing.T) { + core, logs := observer.New(zapcore.InfoLevel) + baseLogger := zap.New(core) + + ctx, logger := SetupFlow( + nilContext, + baseLogger, + "user.create", + zap.String("request.id", "req-7"), + zap.String("enduser.id", "user-42"), + zap.String("enduser.username", "alice"), + zap.String("enduser.name", "Alice"), + zap.String("service.name", "account-api"), + zap.String("route", "/users"), + ) + ctx = WithReason(ctx, "duplicate_email") + ctx = WithErrorType(ctx, errutil.ALREADY_EXISTS) + logger = WithEventOutcome(EventOutcomeFailure, logger) + + if ctx == nil { + t.Fatal("SetupFlow returned nil context") + } + if logger == nil { + t.Fatal("SetupFlow returned nil logger") + } + + Info(ctx, logger, "flow initialized") + + if logs.Len() != 1 { + t.Fatalf("expected 1 log entry, got %d", logs.Len()) + } + + fields := logs.All()[0].ContextMap() + want := map[string]any{ + "request.id": "req-7", + "enduser.id": "user-42", + "enduser.username": "alice", + "enduser.name": "Alice", + "service.name": "account-api", + "event.name": "user.create", + "event.outcome": "failure", + "event.reason": "duplicate_email", + "error.type": "ALREADY_EXISTS", + "route": "/users", + } + + for key, value := range want { + if got := fields[key]; got != value { + t.Fatalf("field %q = %v, want %v", key, got, value) + } + } +} + +func TestSetupFlowUsesSafeDefaults(t *testing.T) { + ctx, logger := SetupFlow(nilContext, nil, "") + + if ctx == nil { + t.Fatal("SetupFlow returned nil context") + } + if logger == nil { + t.Fatal("SetupFlow returned nil logger") + } +} diff --git a/pkg/log/logger.go b/pkg/log/logger.go index 6d7e612..f76a1bb 100644 --- a/pkg/log/logger.go +++ b/pkg/log/logger.go @@ -5,14 +5,20 @@ import ( "fmt" "os" "path/filepath" + "runtime" "strings" - "go.opentelemetry.io/otel/trace" + errutil "github.com/NYCU-SDC/summer/pkg/error" "go.uber.org/zap" "go.uber.org/zap/zapcore" ) -// ZapProductionConfig returns a zap.Config same as zap.NewProduction() but without sampling +// ZapProductionConfig returns the default production zap config for the project. +// +// It is equivalent to zap.NewProductionConfig with sampling disabled, JSON +// encoding, stdout as both the normal and error output, Info as the default +// level, and stack traces disabled. Use this config for services where logs are +// consumed by a collector or log aggregation system. func ZapProductionConfig() zap.Config { return zap.Config{ Level: zap.NewAtomicLevelAt(zap.InfoLevel), @@ -25,7 +31,11 @@ func ZapProductionConfig() zap.Config { } } -// ZapDevelopmentConfig returns a zap.Config same as zap.NewProduction() but with more pretty output +// ZapDevelopmentConfig returns a development zap config optimized for local use. +// +// It writes colorized console logs, enables Debug level logs, writes internal +// zap errors to stderr, and formats caller paths relative to the current working +// directory so IDE consoles can open the referenced source location. func ZapDevelopmentConfig() zap.Config { rootDir, _ := os.Getwd() @@ -45,38 +55,185 @@ func ZapDevelopmentConfig() zap.Config { return config } -// WithContext parses the context and adds the trace ID to the logger if available -func WithContext(ctx context.Context, logger *zap.Logger) *zap.Logger { +// Constructs returns a logger enriched with fields carried by ctx. +// +// The returned logger includes fields from WithFields, active OpenTelemetry +// trace/span metadata, and user/request metadata recorded through the context +// helper functions in with.go. A nil logger is treated as zap.NewNop so callers +// can use this function safely in optional logging paths. +// +// Constructs does not add caller code fields. The level helpers in this file add +// those fields at the actual log call site. +func Constructs(ctx context.Context, logger *zap.Logger) *zap.Logger { + if logger == nil { + logger = zap.NewNop() + } + if ctx == nil { return logger } - spanCtx := trace.SpanFromContext(ctx).SpanContext() - if spanCtx.HasTraceID() { - logger = logger.With(zap.String("trace_id", spanCtx.TraceID().String())) + if fields, ok := ctx.Value(contextFieldsKey{}).(contextFields); ok && len(fields) > 0 { + zapFields := make([]zap.Field, 0, len(fields)) + for _, field := range fields { + zapFields = append(zapFields, field) + } + + logger = logger.With(zapFields...) } - if spanCtx.HasSpanID() { - logger = logger.With(zap.String("span_id", spanCtx.SpanID().String())) + logger = WithTraceContext(ctx, logger) + logger = WithUserContext(ctx, logger) + + return logger +} + +// Debug logs msg at Debug level with fields from ctx and the call site. +// +// Use Debug for diagnostic details that are useful during development or +// investigation but too noisy for normal production operation. +func Debug(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + logger = Constructs(ctx, logger) + fields = append(fields, codeFields(1)...) + logger.Debug(msg, fields...) +} + +// Info logs msg at Info level with fields from ctx and the call site. +// +// Use Info for successful lifecycle events and expected state transitions that +// operators may need to understand normal system behavior. +func Info(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + logger = Constructs(ctx, logger) + fields = append(fields, codeFields(1)...) + logger.Info(msg, fields...) +} + +// Warn logs msg at Warn level with fields from ctx and the call site. +// +// Use Warn for recoverable failures, degraded behavior, retries, or rejected +// inputs that do not represent a server-side fault. +func Warn(ctx context.Context, logger *zap.Logger, msg string, fields ...zap.Field) { + logger = Constructs(ctx, logger) + fields = append(fields, codeFields(1)...) + logger.Warn(msg, fields...) +} + +// Error logs msg at Error level with fields from ctx, err, and the call site. +// +// When err is non-nil, Error adds zap.Error, error.message, +// exception.message, exception.type, exception.stacktrace, any error.type from +// errutil.ErrorTypeCarrier, and any structured error.info fields from +// errutil.InfoCarrier. +func Error(ctx context.Context, logger *zap.Logger, msg string, err error, fields ...zap.Field) { + logger = Constructs(ctx, logger) + + if err != nil { + fields = append(fields, errutil.ErrorFieldsWithStacktrace(err)...) } + fields = append(fields, codeFields(1)...) + logger.Error(msg, fields...) +} - if ctx.Value("user_id") != nil { - logger = logger.With(zap.Any("user_id", ctx.Value("user_id"))) +// DPanic logs msg at DPanic level with fields from ctx, err, and the call site. +// +// In zap development mode this panics after writing the log entry. In production +// mode it logs as an error. Use this for impossible states that should fail fast +// in development but should not necessarily terminate production services. +func DPanic(ctx context.Context, logger *zap.Logger, msg string, err error, fields ...zap.Field) { + logger = Constructs(ctx, logger) + if err != nil { + fields = append(fields, errutil.ErrorFieldsWithStacktrace(err)...) } + fields = append(fields, codeFields(1)...) + logger.DPanic(msg, fields...) +} - if ctx.Value("username") != nil { - logger = logger.With(zap.Any("username", ctx.Value("username"))) +// Panic logs msg at Panic level with fields from ctx, err, and the call site. +// +// It writes the log entry and then panics. Use this only when the caller is +// intentionally aborting the current control flow. +func Panic(ctx context.Context, logger *zap.Logger, msg string, err error, fields ...zap.Field) { + logger = Constructs(ctx, logger) + if err != nil { + fields = append(fields, errutil.ErrorFieldsWithStacktrace(err)...) } + fields = append(fields, codeFields(1)...) + logger.Panic(msg, fields...) +} - if ctx.Value("name") != nil { - logger = logger.With(zap.Any("display-name", ctx.Value("name"))) +// Fatal logs msg at Fatal level with fields from ctx, err, and the call site. +// +// It writes the log entry and then terminates the process through zap's fatal +// behavior. Use this only for unrecoverable process startup or runtime failures. +func Fatal(ctx context.Context, logger *zap.Logger, msg string, err error, fields ...zap.Field) { + logger = Constructs(ctx, logger) + if err != nil { + fields = append(fields, errutil.ErrorFieldsWithStacktrace(err)...) } + fields = append(fields, codeFields(1)...) + logger.Fatal(msg, fields...) +} - return logger +// codeFields returns source location fields for the caller. +// +// The fields follow OpenTelemetry-style names where possible: +// code.file.path, code.file.name, code.line.number, code.function.name, and +// code.namespace. +func codeFields(skip int) []zap.Field { + pcs := make([]uintptr, 1) + + n := runtime.Callers(skip+2, pcs) + if n == 0 { + return nil + } + + frames := runtime.CallersFrames(pcs[:n]) + frame, _ := frames.Next() + + namespace, function := splitFunction(frame.Function) + + return []zap.Field{ + zap.String("code.file.path", trimWorkdir(frame.File)), + zap.String("code.file.name", filepath.Base(frame.File)), + zap.Int("code.line.number", frame.Line), + zap.String("code.function.name", function), + zap.String("code.namespace", namespace), + } +} + +// splitFunction splits a fully qualified Go function name into namespace and name. +func splitFunction(full string) (namespace string, function string) { + i := strings.LastIndex(full, ".") + if i == -1 { + return "", full + } + + return full[:i], full[i+1:] } -// relativePrettyCallerEncoder returns a zapcore.CallerEncoder that formats the caller path relative to the root directory -// it enables clickable links in the GoLand console output +// trimWorkdir returns path relative to the current working directory when possible. +func trimWorkdir(path string) string { + wd, err := os.Getwd() + if err != nil || wd == "" { + return path + } + + rel, err := filepath.Rel(wd, path) + if err != nil { + return path + } + + if strings.HasPrefix(rel, "..") || filepath.IsAbs(rel) { + return path + } + + return rel +} + +// relativePrettyCallerEncoder formats zap caller paths for local development. +// +// Paths inside rootDir are rendered as relative file:line strings. External +// paths keep only the last few path components and are prefixed with external/. func relativePrettyCallerEncoder(rootDir string) zapcore.CallerEncoder { const fixedWidth = 40 @@ -89,16 +246,18 @@ func relativePrettyCallerEncoder(rootDir string) zapcore.CallerEncoder { } else { parts := strings.Split(caller.File, string(filepath.Separator)) - lastN := 3 + const lastN = 3 if len(parts) > lastN { parts = parts[len(parts)-lastN:] } + callerStr = fmt.Sprintf("external/%s:%d", filepath.Join(parts...), caller.Line) } if len(callerStr) < fixedWidth { callerStr += strings.Repeat(" ", fixedWidth-len(callerStr)) } + callerStr += "\t" enc.AppendString(callerStr) } diff --git a/pkg/log/with.go b/pkg/log/with.go new file mode 100644 index 0000000..707d663 --- /dev/null +++ b/pkg/log/with.go @@ -0,0 +1,247 @@ +package logutil + +import ( + "context" + + errutil "github.com/NYCU-SDC/summer/pkg/error" + "go.opentelemetry.io/otel/trace" + "go.uber.org/zap" +) + +type contextFieldsKey struct{} + +type contextFields map[string]zap.Field + +type userIDKey struct{} +type usernameKey struct{} +type displayNameKey struct{} +type requestIDKey struct{} + +// WithFields returns a child context enriched with structured logging fields. +// +// The fields are later injected into a logger by Constructs or by the level +// helpers in logger.go. Fields with an empty key are ignored. Fields with the +// same key replace earlier values so a log entry does not emit duplicate keys. +func WithFields(ctx context.Context, fields ...zap.Field) context.Context { + if ctx == nil { + ctx = context.Background() + } + + existing, _ := ctx.Value(contextFieldsKey{}).(contextFields) + + next := make(contextFields, len(existing)+len(fields)) + for key, field := range existing { + next[key] = field + } + + for _, field := range fields { + if field.Key == "" { + continue + } + + next[field.Key] = field + } + + return context.WithValue(ctx, contextFieldsKey{}, next) +} + +// WithUserID returns a child context carrying the authenticated user's ID. +// +// Constructs emits this value as enduser.id. Empty user IDs are ignored. +func WithUserID(ctx context.Context, userID string) context.Context { + if ctx == nil { + ctx = context.Background() + } + + if userID == "" { + return ctx + } + + return context.WithValue(ctx, userIDKey{}, userID) +} + +// WithUsername returns a child context carrying the authenticated username. +// +// Constructs emits this value as enduser.username. Empty usernames are ignored. +func WithUsername(ctx context.Context, username string) context.Context { + if ctx == nil { + ctx = context.Background() + } + + if username == "" { + return ctx + } + + return context.WithValue(ctx, usernameKey{}, username) +} + +// WithDisplayName returns a child context carrying the user's display name. +// +// Constructs emits this value as enduser.name. Empty names are ignored. +func WithDisplayName(ctx context.Context, name string) context.Context { + if ctx == nil { + ctx = context.Background() + } + + if name == "" { + return ctx + } + + return context.WithValue(ctx, displayNameKey{}, name) +} + +// WithRequestID returns a child context carrying an application request ID. +// +// Constructs emits this value as request.id. Empty request IDs are ignored. +func WithRequestID(ctx context.Context, requestID string) context.Context { + if ctx == nil { + ctx = context.Background() + } + + if requestID == "" { + return ctx + } + + return context.WithValue(ctx, requestIDKey{}, requestID) +} + +// WithReason returns a child context carrying event.reason. +// +// Use event.reason for the structured reason an event took a branch, failed, +// was rejected, or was skipped. +func WithReason(ctx context.Context, reason string) context.Context { + if ctx == nil { + ctx = context.Background() + } + + if reason == "" { + return ctx + } + + return WithFields(ctx, zap.String("event.reason", reason)) +} + +// WithErrorType returns a child context carrying error.type. +// +// Use error.type for a stable machine-readable error classification. Prefer the +// errutil.ErrorType constants when the error maps to a canonical status-like +// category. +func WithErrorType(ctx context.Context, errorType errutil.ErrorType) context.Context { + if ctx == nil { + ctx = context.Background() + } + + if errorType == "" { + return ctx + } + + return WithFields(ctx, zap.String("error.type", string(errorType))) +} + +// WithTraceContext returns logger enriched with the active span context. +// +// When ctx contains a valid OpenTelemetry span, the returned logger includes +// trace_id, span_id, trace_flags, trace_sampled, and trace_state when present. +// A nil logger is treated as zap.NewNop. +func WithTraceContext(ctx context.Context, logger *zap.Logger) *zap.Logger { + if logger == nil { + logger = zap.NewNop() + } + + if ctx == nil { + return logger + } + + spanCtx := trace.SpanFromContext(ctx).SpanContext() + if !spanCtx.IsValid() { + return logger + } + + fields := []zap.Field{ + zap.String("trace_id", spanCtx.TraceID().String()), + zap.String("span_id", spanCtx.SpanID().String()), + zap.String("trace_flags", spanCtx.TraceFlags().String()), + zap.Bool("trace_sampled", spanCtx.IsSampled()), + } + + if traceState := spanCtx.TraceState().String(); traceState != "" { + fields = append(fields, zap.String("trace_state", traceState)) + } + + return logger.With(fields...) +} + +// WithUserContext returns logger enriched with user and request fields from ctx. +// +// It reads values written by WithUserID, WithUsername, WithDisplayName, and +// WithRequestID. If no values are present, logger is returned unchanged. A nil +// logger is treated as zap.NewNop. +func WithUserContext(ctx context.Context, logger *zap.Logger) *zap.Logger { + if logger == nil { + logger = zap.NewNop() + } + + if ctx == nil { + return logger + } + + fields := make([]zap.Field, 0, 4) + + if userID, ok := ctx.Value(userIDKey{}).(string); ok && userID != "" { + fields = append(fields, zap.String("enduser.id", userID)) + } + + if username, ok := ctx.Value(usernameKey{}).(string); ok && username != "" { + fields = append(fields, zap.String("enduser.username", username)) + } + + if name, ok := ctx.Value(displayNameKey{}).(string); ok && name != "" { + fields = append(fields, zap.String("enduser.name", name)) + } + + if requestID, ok := ctx.Value(requestIDKey{}).(string); ok && requestID != "" { + fields = append(fields, zap.String("request.id", requestID)) + } + + if len(fields) == 0 { + return logger + } + + return logger.With(fields...) +} + +// WithOutcome returns logger enriched with event.outcome. +// +// This string-based helper is useful for custom outcome values. Prefer +// WithEventOutcome when the value fits the EventOutcome constants. +func WithOutcome(outcome string, logger *zap.Logger) *zap.Logger { + if logger == nil || outcome == "" { + return logger + } + + return logger.With(zap.String("event.outcome", outcome)) +} + +// WithEventOutcome returns logger enriched with a typed event.outcome value. +// +// Event outcome describes whether an event succeeded, failed, timed out, was +// cancelled, or has an unknown result. +func WithEventOutcome(outcome EventOutcome, logger *zap.Logger) *zap.Logger { + if logger == nil || outcome == "" { + return logger + } + + return logger.With(zap.String("event.outcome", string(outcome))) +} + +// WithEventName returns logger enriched with event.name. +// +// Use event.name for the stable, human-readable event identity, such as +// "user.login" or "profile.update". +func WithEventName(eventName string, logger *zap.Logger) *zap.Logger { + if logger == nil || eventName == "" { + return logger + } + + return logger.With(zap.String("event.name", eventName)) +} diff --git a/pkg/problem/problem.go b/pkg/problem/problem.go index 6eb1a60..c3c6f33 100644 --- a/pkg/problem/problem.go +++ b/pkg/problem/problem.go @@ -7,7 +7,9 @@ import ( "net/http" "github.com/NYCU-SDC/summer/pkg/database" + errutil "github.com/NYCU-SDC/summer/pkg/error" "github.com/NYCU-SDC/summer/pkg/handler" + logutil "github.com/NYCU-SDC/summer/pkg/log" "github.com/NYCU-SDC/summer/pkg/pagination" "github.com/go-playground/validator/v10" "go.opentelemetry.io/otel" @@ -103,23 +105,52 @@ func (h *HttpWriter) buildProblem(err error) Problem { } // writeProblemResponse writes the Problem struct as JSON to the response writer -func (h *HttpWriter) writeProblemResponse(w http.ResponseWriter, problem Problem, err error, logger *zap.Logger) { - logger = logger.WithOptions(zap.AddCallerSkip(2)) +func (h *HttpWriter) writeProblemResponse(ctx context.Context, w http.ResponseWriter, problem Problem, err error, logger *zap.Logger) { + logger = logutil.Constructs(ctx, logger).WithOptions(zap.AddCallerSkip(2)) - logger.Warn("Handling "+problem.Title, zap.String("problem", problem.Title), zap.Error(err), zap.Int("status", problem.Status), zap.String("type", problem.Type), zap.String("detail", problem.Detail)) + fields := []zap.Field{ + zap.Int("http.status_code", problem.Status), + zap.String("problem.type", problem.Type), + zap.String("problem.title", problem.Title), + zap.String("problem.detail", problem.Detail), + zap.String("error.kind", problemErrorKind(problem.Status)), + } + if problem.Instance != "" { + fields = append(fields, zap.String("problem.instance", problem.Instance)) + } + + if problem.Status >= http.StatusInternalServerError { + fields = append(fields, errutil.ErrorFieldsWithStacktrace(err)...) + logger.Error("request failed", fields...) + } else { + fields = append(fields, errutil.ErrorFields(err)...) + logger.Warn("request failed", fields...) + } w.Header().Set("Content-Type", "application/problem+json") w.WriteHeader(problem.Status) jsonBytes, marshalErr := json.Marshal(problem) if marshalErr != nil { - logger.Error("Failed to marshal problem response", zap.Error(marshalErr)) + marshalFields := []zap.Field{ + zap.Int("http.status_code", http.StatusInternalServerError), + zap.String("problem.title", "Internal Server Error"), + zap.String("error.kind", problemErrorKind(http.StatusInternalServerError)), + } + marshalFields = append(marshalFields, errutil.ErrorFields(marshalErr)...) + logger.Error("problem response marshal failed", marshalFields...) http.Error(w, marshalErr.Error(), http.StatusInternalServerError) return } _, writeErr := w.Write(jsonBytes) if writeErr != nil { - logger.Error("Failed to write problem response", zap.Error(writeErr)) + writeFields := []zap.Field{ + zap.Int("http.status_code", http.StatusInternalServerError), + zap.String("problem.title", "Internal Server Error"), + zap.String("error.kind", problemErrorKind(http.StatusInternalServerError)), + } + writeFields = append(writeFields, errutil.ErrorFields(writeErr)...) + logger.Error("problem response write failed", writeFields...) http.Error(w, writeErr.Error(), http.StatusInternalServerError) return } @@ -134,7 +165,7 @@ func (h *HttpWriter) WriteError(ctx context.Context, w http.ResponseWriter, err } problem := h.buildProblem(err) - h.writeProblemResponse(w, problem, err, logger) + h.writeProblemResponse(ctx, w, problem, err, logger) } func (h *HttpWriter) WriteErrorWithRequest(ctx context.Context, r *http.Request, w http.ResponseWriter, err error, logger *zap.Logger) { @@ -149,7 +180,32 @@ func (h *HttpWriter) WriteErrorWithRequest(ctx context.Context, r *http.Request, if r != nil && r.URL != nil { problem.Instance = r.URL.Path } - h.writeProblemResponse(w, problem, err, logger) + h.writeProblemResponse(ctx, w, problem, err, logger) +} + +func problemErrorKind(status int) string { + switch status { + case http.StatusBadRequest: + return "INVALID_ARGUMENT" + case http.StatusUnauthorized: + return "UNAUTHENTICATED" + case http.StatusForbidden: + return "PERMISSION_DENIED" + case http.StatusNotFound: + return "NOT_FOUND" + case http.StatusConflict: + return "ALREADY_EXISTS" + case http.StatusTooManyRequests: + return "RESOURCE_EXHAUSTED" + case http.StatusRequestTimeout, http.StatusGatewayTimeout: + return "DEADLINE_EXCEEDED" + } + + if status >= http.StatusInternalServerError { + return "INTERNAL" + } + + return "UNKNOWN" } func NewInternalServerProblem(detail string) Problem {