diff --git a/.gitignore b/.gitignore index 174474c57..b5b79232b 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ # Patterns for files created by this project. # For other files, use global gitignore. *.s3db +.idea diff --git a/extra/bunzerolog/README.md b/extra/bunzerolog/README.md new file mode 100644 index 000000000..0cb4da3af --- /dev/null +++ b/extra/bunzerolog/README.md @@ -0,0 +1,87 @@ +# bunzerolog + +bunzerolog is a logging package for Bun that uses zerolog. +This package enables SQL queries executed by Bun to be logged and displayed using zerolog. + +## Installation + +```bash +go get github.com/uptrace/bun/extra/bunzerolog +``` + +## Features + +- Supports setting a `*zerolog.Logger` instance or uses the global logger if not set. +- Supports setting a `*zerolog.Logger` instance using the context. +- Logs general SQL queries with configurable log levels. +- Logs slow SQL queries based on a configurable duration threshold. +- Logs SQL queries that result in errors, for easier debugging. +- Allows for custom log formatting. + +## Usage + +First, import the bunzerolog package: +```go +import "github.com/uptrace/bun/extra/bunzerolog" +``` + +Then, create a new QueryHook and add the hook to `*bun.DB` instance: +```go +import "github.com/rs/zerolog" + +db := bun.NewDB(sqldb, dialect) + +hook := bunzerolog.NewQueryHook( + bunzerolog.WithQueryLogLevel(zerolog.DebugLevel), + bunzerolog.WithSlowQueryLogLevel(zerolog.WarnLevel), + bunzerolog.WithErrorQueryLogLevel(zerolog.ErrorLevel), + bunzerolog.WithSlowQueryThreshold(3 * time.Second), +) + +db.AddQueryHook(hook) +``` + +## Setting a Custom `*zerolog.Logger` Instance + +To set a `*zerolog.Logger` instance, you can use the WithLogger option: + +```go +logger := zerolog.New(os.Stderr).With().Timestamp().Logger() +hook := bunzerolog.NewQueryHook( + bunzerolog.WithLogger(logger), + // other options... +) +``` + +If a `*zerolog.Logger` instance is not set, the logger from the context will be used. + +## Custom Log Formatting + +To customize the log format, you can use the WithLogFormat option: + +```go +customFormat := func(ctx context.Context, event *bun.QueryEvent, zerevent *zerolog.Event) *zerolog.Event { + duration := h.now().Sub(event.StartTime) + + return zerevent. + Err(event.Err). + Str("request_id", requestid.FromContext(ctx)). + Str("query", event.Query). + Str("operation", event.Operation()). + Str("duration", duration.String()) +} + +hook := bunzerolog.NewQueryHook( + bunzerolog.WithLogFormat(customFormat), + // other options... +) +``` + +## Options + +- `WithLogger(logger *zerolog.Logger)`: Sets a `*zerolog.Logger` instance. If not set, the logger from context will be used. +- `WithQueryLogLevel(level zerolog.Level)`: Sets the log level for general queries. +- `WithSlowQueryLogLevel(level zerolog.Level)`: Sets the log level for slow queries. +- `WithErrorQueryLogLevel(level zerolog.Level)`: Sets the log level for queries that result in errors. +- `WithSlowQueryThreshold(threshold time.Duration)`: Sets the duration threshold for identifying slow queries. +- `WithLogFormat(f logFormat)`: Sets the custom format for slog output. diff --git a/extra/bunzerolog/hook.go b/extra/bunzerolog/hook.go deleted file mode 100644 index de23efb40..000000000 --- a/extra/bunzerolog/hook.go +++ /dev/null @@ -1,43 +0,0 @@ -package bunzerolog - -import ( - "context" - "database/sql" - "errors" - "time" - - "github.com/rs/zerolog/log" - - "github.com/uptrace/bun" -) - -var _ bun.QueryHook = (*QueryHook)(nil) - -type QueryHook struct{} - -// BeforeQuery before query zerolog hook. -func (h *QueryHook) BeforeQuery(ctx context.Context, _ *bun.QueryEvent) context.Context { - return ctx -} - -// AfterQuery after query zerolog hook. -func (h *QueryHook) AfterQuery(ctx context.Context, event *bun.QueryEvent) { - l := log.Ctx(ctx).With(). - Str("query", event.Query). - Str("operation", event.Operation()). - Str("duration", time.Since(event.StartTime).String()). - Logger() - - if event.Err != nil { - // do not log sql.ErrNoRows as real error - if errors.Is(event.Err, sql.ErrNoRows) { - l.Warn().Err(event.Err).Send() - return - } - - l.Err(event.Err).Send() - return - } - - l.Debug().Send() -} diff --git a/extra/bunzerolog/zerohook.go b/extra/bunzerolog/zerohook.go new file mode 100644 index 000000000..e5bda9960 --- /dev/null +++ b/extra/bunzerolog/zerohook.go @@ -0,0 +1,132 @@ +package bunzerolog + +// bunslog provides logging functionalities for Bun using slog. +// This package allows SQL queries issued by Bun to be displayed using slog. + +import ( + "context" + "database/sql" + "errors" + "time" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" + + "github.com/uptrace/bun" +) + +var _ bun.QueryHook = (*QueryHook)(nil) + +// Option is a function that configures a QueryHook. +type Option func(*QueryHook) + +// WithLogger sets the *zerolog.Logger instance. +func WithLogger(logger *zerolog.Logger) Option { + return func(h *QueryHook) { + h.logger = logger + } +} + +// WithQueryLogLevel sets the log level for general queries. +func WithQueryLogLevel(level zerolog.Level) Option { + return func(h *QueryHook) { + h.queryLogLevel = level + } +} + +// WithSlowQueryLogLevel sets the log level for slow queries. +func WithSlowQueryLogLevel(level zerolog.Level) Option { + return func(h *QueryHook) { + h.slowQueryLogLevel = level + } +} + +// WithErrorQueryLogLevel sets the log level for queries that result in an error. +func WithErrorQueryLogLevel(level zerolog.Level) Option { + return func(h *QueryHook) { + h.errorLogLevel = level + } +} + +// WithSlowQueryThreshold sets the duration threshold for identifying slow queries. +func WithSlowQueryThreshold(threshold time.Duration) Option { + return func(h *QueryHook) { + h.slowQueryThreshold = threshold + } +} + +// WithLogFormat sets the custom format for slog output. +func WithLogFormat(f LogFormatFn) Option { + return func(h *QueryHook) { + h.logFormat = f + } +} + +type LogFormatFn func(ctx context.Context, event *bun.QueryEvent, zeroctx *zerolog.Event) *zerolog.Event + +// QueryHook is a hook for Bun that enables logging with slog. +// It implements bun.QueryHook interface. +type QueryHook struct { + logger *zerolog.Logger + queryLogLevel zerolog.Level + slowQueryLogLevel zerolog.Level + errorLogLevel zerolog.Level + slowQueryThreshold time.Duration + logFormat LogFormatFn + now func() time.Time +} + +// NewQueryHook initializes a new QueryHook with the given options. +func NewQueryHook(opts ...Option) *QueryHook { + h := &QueryHook{ + queryLogLevel: zerolog.DebugLevel, + slowQueryLogLevel: zerolog.WarnLevel, + errorLogLevel: zerolog.ErrorLevel, + now: time.Now, + } + + for _, opt := range opts { + opt(h) + } + + // use default format + if h.logFormat == nil { + h.logFormat = func(ctx context.Context, event *bun.QueryEvent, zerevent *zerolog.Event) *zerolog.Event { + duration := h.now().Sub(event.StartTime) + + return zerevent. + Err(event.Err). + Str("query", event.Query). + Str("operation", event.Operation()). + Str("duration", duration.String()) + } + } + + return h +} + +// BeforeQuery is called before a query is executed. +func (h *QueryHook) BeforeQuery(ctx context.Context, event *bun.QueryEvent) context.Context { + return ctx +} + +// AfterQuery is called after a query is executed. +// It logs the query based on its duration and whether it resulted in an error. +func (h *QueryHook) AfterQuery(ctx context.Context, event *bun.QueryEvent) { + level := h.queryLogLevel + duration := h.now().Sub(event.StartTime) + if h.slowQueryThreshold > 0 && h.slowQueryThreshold <= duration { + level = h.slowQueryLogLevel + } + + if event.Err != nil && !errors.Is(event.Err, sql.ErrNoRows) { + level = h.errorLogLevel + } + + l := h.logger + if l == nil { + l = log.Ctx(ctx) + } + + h.logFormat(ctx, event, l.WithLevel(level)).Send() +} diff --git a/extra/bunzerolog/zerohook_test.go b/extra/bunzerolog/zerohook_test.go new file mode 100644 index 000000000..8ff9cf703 --- /dev/null +++ b/extra/bunzerolog/zerohook_test.go @@ -0,0 +1,200 @@ +package bunzerolog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "reflect" + "testing" + "time" + + "github.com/rs/zerolog" + + "github.com/uptrace/bun" +) + +type Record struct { + Level zerolog.Level `json:"level"` + Error string `json:"error"` + Status string `json:"status"` + Query string `json:"query"` + Operation string `json:"operation"` + Duration string `json:"duration"` +} + +func TestAfterQuery(t *testing.T) { + testCases := []struct { + ctx context.Context + name string + queryLogLevel zerolog.Level + errorQueryLogLevel zerolog.Level + slowQueryLogLevel zerolog.Level + slowQueryThreshold time.Duration + event *bun.QueryEvent + now func() time.Time + expect Record + }{ + { + ctx: context.Background(), + name: "basic query log", + queryLogLevel: zerolog.DebugLevel, + event: &bun.QueryEvent{ + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + StartTime: time.Date(2006, 1, 2, 15, 4, 2, 0, time.Local), + Err: nil, + }, + now: func() time.Time { return time.Date(2006, 1, 2, 15, 4, 5, 0, time.Local) }, + expect: Record{ + Level: zerolog.DebugLevel, + Error: "", + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Operation: "SELECT", + Duration: "3s", + }, + }, + { + ctx: context.Background(), + name: "does not become slow query when below slowQueryThreshold", + queryLogLevel: zerolog.DebugLevel, + slowQueryLogLevel: zerolog.WarnLevel, + slowQueryThreshold: 3 * time.Second, + event: &bun.QueryEvent{ + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + StartTime: time.Date(2006, 1, 2, 15, 4, 3, 0, time.Local), + Err: nil, + }, + now: func() time.Time { return time.Date(2006, 1, 2, 15, 4, 5, 0, time.Local) }, + expect: Record{ + Level: zerolog.DebugLevel, + Error: "", + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Operation: "SELECT", + Duration: "2s", + }, + }, + { + ctx: context.Background(), + name: "becomes slow query when at or above slowQueryThreshold", + slowQueryLogLevel: zerolog.WarnLevel, + slowQueryThreshold: 3 * time.Second, + event: &bun.QueryEvent{ + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + StartTime: time.Date(2006, 1, 2, 15, 4, 2, 0, time.Local), + Err: nil, + }, + now: func() time.Time { return time.Date(2006, 1, 2, 15, 4, 5, 0, time.Local) }, + expect: Record{ + Level: zerolog.WarnLevel, + Error: "", + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Operation: "SELECT", + Duration: "3s", + }, + }, + { + ctx: context.Background(), + name: "error query log", + errorQueryLogLevel: zerolog.ErrorLevel, + event: &bun.QueryEvent{ + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Err: errors.New("unexpected error"), + StartTime: time.Date(2006, 1, 2, 15, 4, 2, 0, time.Local), + }, + now: func() time.Time { return time.Date(2006, 1, 2, 15, 4, 5, 0, time.Local) }, + expect: Record{ + Level: zerolog.ErrorLevel, + Error: "unexpected error", + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Operation: "SELECT", + Duration: "3s", + }, + }, + } + + for _, tc := range testCases { + t.Run(tc.name+"(with global logger)", func(t *testing.T) { + var buf bytes.Buffer + ctx := zerolog.New(&buf).Level(tc.expect.Level).WithContext(tc.ctx) + + hook := NewQueryHook( + WithQueryLogLevel(tc.queryLogLevel), + WithErrorQueryLogLevel(tc.errorQueryLogLevel), + WithSlowQueryLogLevel(tc.slowQueryLogLevel), + WithSlowQueryThreshold(tc.slowQueryThreshold), + ) + hook.now = tc.now + hook.AfterQuery(ctx, tc.event) + + var result Record + if err := json.Unmarshal(buf.Bytes(), &result); err != nil { + t.Fatalf("failed to unmarshal JSON: %v", err) + } + + if !reflect.DeepEqual(tc.expect, result) { + t.Errorf("unexpected logging want=%+v but got=%+v", tc.expect, result) + } + }) + + t.Run(tc.name+"(with logger instance)", func(t *testing.T) { + var buf bytes.Buffer + logger := zerolog.New(&buf).Level(tc.expect.Level) + + hook := NewQueryHook( + WithQueryLogLevel(tc.queryLogLevel), + WithErrorQueryLogLevel(tc.errorQueryLogLevel), + WithSlowQueryLogLevel(tc.slowQueryLogLevel), + WithSlowQueryThreshold(tc.slowQueryThreshold), + WithLogger(&logger), + ) + hook.now = tc.now + hook.AfterQuery(tc.ctx, tc.event) + + var result Record + if err := json.Unmarshal(buf.Bytes(), &result); err != nil { + t.Fatalf("failed to unmarshal JSON: %v", err) + } + + if !reflect.DeepEqual(tc.expect, result) { + t.Errorf("unexpected logging want=%+v but got=%+v", tc.expect, result) + } + }) + } + + t.Run("custom format", func(t *testing.T) { + expect := struct { + Level zerolog.Level + Query string + }{ + Level: zerolog.DebugLevel, + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + } + var buf bytes.Buffer + ctx := zerolog.New(&buf).Level(zerolog.DebugLevel).WithContext(context.Background()) + + hook := NewQueryHook( + WithLogFormat(func(ctx context.Context, event *bun.QueryEvent, zeroevent *zerolog.Event) *zerolog.Event { + return zeroevent.Str("query", event.Query) + }), + ) + hook.now = func() time.Time { return time.Date(2006, 1, 2, 15, 4, 5, 0, time.Local) } + event := &bun.QueryEvent{ + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Err: nil, + StartTime: time.Date(2006, 1, 2, 15, 4, 2, 0, time.Local), + } + hook.AfterQuery(ctx, event) + + var result struct { + Level zerolog.Level + Query string + } + if err := json.Unmarshal(buf.Bytes(), &result); err != nil { + t.Fatalf("failed to unmarshal JSON: %v", err) + } + + if !reflect.DeepEqual(expect, result) { + t.Errorf("unexpected logging want=%+v but got=%+v", expect, result) + } + }) +}