From 495336731da0a995aa28c7bc84345c7825408e48 Mon Sep 17 00:00:00 2001 From: Yuki Hirasawa <48427044+hirasawayuki@users.noreply.github.com> Date: Wed, 27 Sep 2023 21:16:21 +0900 Subject: [PATCH] feat: bunslog.QueryHook for Bun logging using `log/slog` (#904) * feat: logging package for Bun that uses `log/slog` * fix: documentation and log level adjustments * chore: bump Go version to 1.21.x in tests --- .github/workflows/build.yml | 2 +- extra/bunslog/README.md | 77 +++++++++++++ extra/bunslog/bunslog.go | 134 +++++++++++++++++++++++ extra/bunslog/bunslog_test.go | 201 ++++++++++++++++++++++++++++++++++ extra/bunslog/go.mod | 13 +++ extra/bunslog/go.sum | 25 +++++ 6 files changed, 451 insertions(+), 1 deletion(-) create mode 100644 extra/bunslog/README.md create mode 100644 extra/bunslog/bunslog.go create mode 100644 extra/bunslog/bunslog_test.go create mode 100644 extra/bunslog/go.mod create mode 100644 extra/bunslog/go.sum diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 392c84c00..e1dac7f85 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -14,7 +14,7 @@ jobs: strategy: fail-fast: false matrix: - go-version: [1.19.x, 1.20.x] + go-version: [1.21.x] services: postgres: diff --git a/extra/bunslog/README.md b/extra/bunslog/README.md new file mode 100644 index 000000000..dae6303e4 --- /dev/null +++ b/extra/bunslog/README.md @@ -0,0 +1,77 @@ +# bunslog + +bunslog is a logging package for Bun that uses slog. +This package enables SQL queries executed by Bun to be logged and displayed using slog. + +## Installation + +```bash +go get github.com/uptrace/bun/extra/bunslog +``` + +## Features + +- Supports setting a `*slog.Logger` instance or uses the global logger if not set. +- 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 bunslog package: +```go +import "github.com/uptrace/bun/extra/bunslog" +``` + +Then, create a new QueryHook and add the hook to `*bun.DB` instance: +```go +db := bun.NewDB(sqldb, dialect) + +hook := bunslog.NewQueryHook( + bunslog.WithQueryLogLevel(slog.LevelDebug), + bunslog.WithSlowQueryLogLevel(slog.LevelWarn), + bunslog.WithErrorQueryLogLevel(slog.LevelError), + bunslog.WithSlowQueryThreshold(3 * time.Second), +) + +db.AddQueryHook(hook) +``` + +## Setting a Custom `*slog.Logger` Instance + +To set a `*slog.Logger` instance, you can use the WithLogger option: + +```go +logger := slog.NewLogger() +hook := bunslog.NewQueryHook( + bunslog.WithLogger(logger), + // other options... +) +``` + +If a `*slog.Logger` instance is not set, the global logger will be used. + +## Custom Log Formatting + +To customize the log format, you can use the WithLogFormat option: + +```go +customFormat := func(event *bun.QueryEvent) []slog.Attr { + // your custom formatting logic here +} + +hook := bunslog.NewQueryHook( + bunslog.WithLogFormat(customFormat), + // other options... +) +``` + +## Options + +- `WithLogger(logger *slog.Logger)`: Sets a `*slog.Logger` instance. If not set, the global logger will be used. +- `WithQueryLogLevel(level slog.Level)`: Sets the log level for general queries. +- `WithSlowQueryLogLevel(level slog.Level)`: Sets the log level for slow queries. +- `WithErrorQueryLogLevel(level slog.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/bunslog/bunslog.go b/extra/bunslog/bunslog.go new file mode 100644 index 000000000..9d35cc8e3 --- /dev/null +++ b/extra/bunslog/bunslog.go @@ -0,0 +1,134 @@ +package bunslog + +// 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" + "log/slog" + "time" + + "github.com/uptrace/bun" +) + +// Option is a function that configures a QueryHook. +type Option func(*QueryHook) + +// WithLogger sets the *slog.Logger instance. +func WithLogger(logger *slog.Logger) Option { + return func(h *QueryHook) { + h.logger = logger + } +} + +// WithQueryLogLevel sets the log level for general queries. +func WithQueryLogLevel(level slog.Level) Option { + return func(h *QueryHook) { + h.queryLogLevel = level + } +} + +// WithSlowQueryLogLevel sets the log level for slow queries. +func WithSlowQueryLogLevel(level slog.Level) Option { + return func(h *QueryHook) { + h.slowQueryLogLevel = level + } +} + +// WithErrorQueryLogLevel sets the log level for queries that result in an error. +func WithErrorQueryLogLevel(level slog.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 logFormat) Option { + return func(h *QueryHook) { + h.logFormat = f + } +} + +type logFormat func(event *bun.QueryEvent) []slog.Attr + +// QueryHook is a hook for Bun that enables logging with slog. +// It implements bun.QueryHook interface. +type QueryHook struct { + logger *slog.Logger + queryLogLevel slog.Level + slowQueryLogLevel slog.Level + errorLogLevel slog.Level + slowQueryThreshold time.Duration + logFormat func(event *bun.QueryEvent) []slog.Attr + now func() time.Time +} + +// NewQueryHook initializes a new QueryHook with the given options. +func NewQueryHook(opts ...Option) *QueryHook { + h := &QueryHook{ + queryLogLevel: slog.LevelDebug, + slowQueryLogLevel: slog.LevelWarn, + errorLogLevel: slog.LevelError, + now: time.Now, + } + + for _, opt := range opts { + opt(h) + } + + // use default format + if h.logFormat == nil { + h.logFormat = func(event *bun.QueryEvent) []slog.Attr { + duration := h.now().Sub(event.StartTime) + + return []slog.Attr{ + slog.Any("error", event.Err), + slog.String("operation", event.Operation()), + slog.String("query", event.Query), + slog.String("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 + } + + attrs := h.logFormat(event) + if h.logger != nil { + h.logger.LogAttrs(ctx, level, "", attrs...) + return + } + + slog.LogAttrs(ctx, level, "", attrs...) +} + +var ( + _ bun.QueryHook = (*QueryHook)(nil) +) diff --git a/extra/bunslog/bunslog_test.go b/extra/bunslog/bunslog_test.go new file mode 100644 index 000000000..aed2d60c9 --- /dev/null +++ b/extra/bunslog/bunslog_test.go @@ -0,0 +1,201 @@ +package bunslog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "log/slog" + "reflect" + "testing" + "time" + + "github.com/uptrace/bun" +) + +type Record struct { + Level slog.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 slog.Level + errorQueryLogLevel slog.Level + slowQueryLogLevel slog.Level + slowQueryThreshold time.Duration + event *bun.QueryEvent + now func() time.Time + expect Record + }{ + { + ctx: context.Background(), + name: "basic query log", + queryLogLevel: slog.LevelDebug, + 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: slog.LevelDebug, + 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: slog.LevelDebug, + slowQueryLogLevel: slog.LevelWarn, + 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: slog.LevelDebug, + 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: slog.LevelWarn, + 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: slog.LevelWarn, + Error: "", + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + Operation: "SELECT", + Duration: "3s", + }, + }, + { + ctx: context.Background(), + name: "error query log", + errorQueryLogLevel: slog.LevelError, + 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: slog.LevelError, + 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 + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: tc.expect.Level}))) + + hook := NewQueryHook( + WithQueryLogLevel(tc.queryLogLevel), + WithErrorQueryLogLevel(tc.errorQueryLogLevel), + WithSlowQueryLogLevel(tc.slowQueryLogLevel), + WithSlowQueryThreshold(tc.slowQueryThreshold), + ) + 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(tc.name+"(with logger instance)", func(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{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 slog.Level + Query string + }{ + Level: slog.LevelDebug, + Query: "SELECT `user`.`id`, `user`.`name`, `user`.`email` FROM `users`", + } + var buf bytes.Buffer + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + + hook := NewQueryHook( + WithLogFormat(func(event *bun.QueryEvent) []slog.Attr { + return []slog.Attr{ + slog.String("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(context.Background(), event) + + var result struct { + Level slog.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) + } + }) +} diff --git a/extra/bunslog/go.mod b/extra/bunslog/go.mod new file mode 100644 index 000000000..e1b685d68 --- /dev/null +++ b/extra/bunslog/go.mod @@ -0,0 +1,13 @@ +module github.com/uptrace/bun/extra/bunslog + +go 1.21 + +require github.com/uptrace/bun v1.1.16 + +require ( + github.com/jinzhu/inflection v1.0.0 // indirect + github.com/tmthrgd/go-hex v0.0.0-20190904060850-447a3041c3bc // indirect + github.com/vmihailenco/msgpack/v5 v5.3.5 // indirect + github.com/vmihailenco/tagparser/v2 v2.0.0 // indirect + golang.org/x/sys v0.12.0 // indirect +) diff --git a/extra/bunslog/go.sum b/extra/bunslog/go.sum new file mode 100644 index 000000000..745284e3f --- /dev/null +++ b/extra/bunslog/go.sum @@ -0,0 +1,25 @@ +github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/jinzhu/inflection v1.0.0 h1:K317FqzuhWc8YvSVlFMCCUb36O/S9MCKRDI7QkRKD/E= +github.com/jinzhu/inflection v1.0.0/go.mod h1:h+uFLlag+Qp1Va5pdKtLDYj+kHp5pxUVkryuEj+Srlc= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk= +github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4= +github.com/tmthrgd/go-hex v0.0.0-20190904060850-447a3041c3bc h1:9lRDQMhESg+zvGYmW5DyG0UqvY96Bu5QYsTLvCHdrgo= +github.com/tmthrgd/go-hex v0.0.0-20190904060850-447a3041c3bc/go.mod h1:bciPuU6GHm1iF1pBvUfxfsH0Wmnc2VbpgvbI9ZWuIRs= +github.com/uptrace/bun v1.1.16 h1:cn9cgEMFwcyYRsQLfxCRMUxyK1WaHwOVrR3TvzEFZ/A= +github.com/uptrace/bun v1.1.16/go.mod h1:7HnsMRRvpLFUcquJxp22JO8PsWKpFQO/gNXqqsuGWg8= +github.com/vmihailenco/msgpack/v5 v5.3.5 h1:5gO0H1iULLWGhs2H5tbAHIZTV8/cYafcFOr9znI5mJU= +github.com/vmihailenco/msgpack/v5 v5.3.5/go.mod h1:7xyJ9e+0+9SaZT0Wt1RGleJXzli6Q/V5KbhBonMG9jc= +github.com/vmihailenco/tagparser/v2 v2.0.0 h1:y09buUbR+b5aycVFQs/g70pqKVZNBmxwAhO7/IwNM9g= +github.com/vmihailenco/tagparser/v2 v2.0.0/go.mod h1:Wri+At7QHww0WTrCBeu4J6bNtoV6mEfg5OIWRZA9qds= +golang.org/x/sys v0.12.0 h1:CM0HF96J0hcLAwsHPJZjfdNzs0gftsLfgKt57wWHJ0o= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=