Skip to content

Improve log level and argument format #50

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
akm merged 11 commits into from
Aug 6, 2025
Merged

Improve log level and argument format #50

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
849d84b
✨ Modify log level for start log in order to reduce logs
akm Aug 6, 2025
c445e8a
✅ Follow modification of start log level
akm Aug 6, 2025
e1d755c
✨ Add functions to format Value or NamedValue
akm Aug 6, 2025
9dbb1a7
✅ Follow format modification of args
akm Aug 6, 2025
d2ce9fb
📝 Update log examples in examples/logs-*/results
akm Aug 6, 2025
aff5759
✨ Modify log levels for Conn.PrepareContext method and Stmt methods
akm Aug 6, 2025
213fbd2
✅ Follow log level modification
akm Aug 6, 2025
aad8eb5
📝 Update log examples in examples/logs-*/results
akm Aug 6, 2025
c1999e8
♻️ Extract functions from formatNamedValues
akm Aug 6, 2025
b31ca99
✅ Use t.Parallel
akm Aug 6, 2025
b9b5d9c
✅ Add tests for formatValue
akm Aug 6, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 3 additions & 4 deletions conn.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,6 @@ import (
"context"
"database/sql/driver"
"errors"
"fmt"
"log/slog"
)

Expand Down Expand Up @@ -47,7 +46,7 @@ func defaultConnOptions(driverName string, msgb StepEventMsgBuilder) *connOption
Close: *defaultStepOptions(msgb, StepConnClose, LevelInfo),

Prepare: *defaultStepOptions(msgb, StepConnPrepare, LevelInfo),
PrepareContext: *defaultStepOptions(msgb, StepConnPrepareContext, LevelInfo),
PrepareContext: *defaultStepOptions(msgb, StepConnPrepareContext, LevelTrace),
StmtIDKey: StmtIDKeyDefault,
StmtOptions: stmtOptions,

Expand Down Expand Up @@ -235,7 +234,7 @@ func (c *connWithContextWrapper) ExecContext(ctx context.Context, query string,
var result driver.Result
lg := c.logger.With(
slog.String("query", query),
slog.String("args", fmt.Sprintf("%+v", args)),
slog.String("args", formatNamedValues(args)),
)
err := ignoreAttr(lg.Step(ctx, &c.options.ExecContext, func() (*slog.Attr, error) {
var err error
Expand All @@ -253,7 +252,7 @@ func (c *connWithContextWrapper) QueryContext(ctx context.Context, query string,
var rows driver.Rows
lg := c.logger.With(
slog.String("query", query),
slog.String("args", fmt.Sprintf("%+v", args)),
slog.String("args", formatNamedValues(args)),
)
err := ignoreAttr(lg.Step(ctx, &c.options.QueryContext, func() (*slog.Attr, error) {
var err error
Expand Down
99 changes: 34 additions & 65 deletions examples/logs-mysql/results/debug-log.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,65 +1,34 @@
time=2025-02-19T08:24:59.722+09:00 level=DEBUG msg=Open driver=mysql dsn=root@tcp(localhost:3306)/app1
time=2025-02-19T08:24:59.722+09:00 level=DEBUG msg=Driver.OpenConnector dsn=root@tcp(localhost:3306)/app1
time=2025-02-19T08:24:59.722+09:00 level=INFO msg=Driver.OpenConnector dsn=root@tcp(localhost:3306)/app1 duration=3208 conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:24:59.722+09:00 level=INFO msg=Open driver=mysql dsn=root@tcp(localhost:3306)/app1 duration=225000
time=2025-02-19T08:24:59.722+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:24:59.722+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:24:59.725+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=2847375 error="driver: bad connection"
time=2025-02-19T08:24:59.725+09:00 level=ERROR msg=Connector.Connect duration=2927833 error="driver: bad connection"
time=2025-02-19T08:24:59.725+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:24:59.725+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:24:59.726+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=977416 error="driver: bad connection"
time=2025-02-19T08:24:59.726+09:00 level=ERROR msg=Connector.Connect duration=1028333 error="driver: bad connection"
time=2025-02-19T08:24:59.726+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:24:59.726+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:24:59.730+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=3485500 error="driver: bad connection"
time=2025-02-19T08:24:59.730+09:00 level=ERROR msg=Connector.Connect duration=3563666 error="driver: bad connection"
time=2025-02-19T08:25:01.731+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:01.731+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:01.735+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=3532208 error="driver: bad connection"
time=2025-02-19T08:25:01.735+09:00 level=ERROR msg=Connector.Connect duration=3716958 error="driver: bad connection"
time=2025-02-19T08:25:01.735+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:01.735+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:01.738+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=3166875 error="driver: bad connection"
time=2025-02-19T08:25:01.738+09:00 level=ERROR msg=Connector.Connect duration=3307167 error="driver: bad connection"
time=2025-02-19T08:25:01.738+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:01.738+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:01.742+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=3507917 error="driver: bad connection"
time=2025-02-19T08:25:01.742+09:00 level=ERROR msg=Connector.Connect duration=3641417 error="driver: bad connection"
time=2025-02-19T08:25:03.743+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:03.743+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:03.747+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=3340041 error="driver: bad connection"
time=2025-02-19T08:25:03.747+09:00 level=ERROR msg=Connector.Connect duration=3583292 error="driver: bad connection"
time=2025-02-19T08:25:03.747+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:03.747+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:03.750+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=2590291 error="driver: bad connection"
time=2025-02-19T08:25:03.750+09:00 level=ERROR msg=Connector.Connect duration=2747792 error="driver: bad connection"
time=2025-02-19T08:25:03.750+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:03.750+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:03.752+09:00 level=ERROR msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=1661208 error="driver: bad connection"
time=2025-02-19T08:25:03.752+09:00 level=ERROR msg=Connector.Connect duration=1868625 error="driver: bad connection"
time=2025-02-19T08:25:05.753+09:00 level=DEBUG msg=Connector.Connect
time=2025-02-19T08:25:05.753+09:00 level=DEBUG msg=Connector.Connect conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:05.757+09:00 level=INFO msg=Connector.Connect conn_id=GcehcYURvlj4lPDG duration=4553417
time=2025-02-19T08:25:05.757+09:00 level=INFO msg=Connector.Connect duration=4614041
time=2025-02-19T08:25:05.758+09:00 level=DEBUG msg=Conn.ExecContext conn_id=GcehcYURvlj4lPDG query="CREATE TABLE IF NOT EXISTS test1 (id INT PRIMARY KEY, name VARCHAR(255))" args=[]
time=2025-02-19T08:25:05.774+09:00 level=INFO msg=Conn.ExecContext conn_id=GcehcYURvlj4lPDG query="CREATE TABLE IF NOT EXISTS test1 (id INT PRIMARY KEY, name VARCHAR(255))" args=[] duration=15872083
time=2025-02-19T08:25:05.774+09:00 level=DEBUG msg=Conn.BeginTx conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:05.774+09:00 level=INFO msg=Conn.BeginTx conn_id=GcehcYURvlj4lPDG duration=311917 tx_id=P_5GU9YZ66Q7cVCQ
time=2025-02-19T08:25:05.774+09:00 level=DEBUG msg=Conn.ExecContext conn_id=GcehcYURvlj4lPDG query="INSERT INTO test1 (id, name) VALUES (?, ?)" args="[{Name: Ordinal:1 Value:1} {Name: Ordinal:2 Value:Alice}]"
time=2025-02-19T08:25:05.775+09:00 level=INFO msg=Conn.ExecContext conn_id=GcehcYURvlj4lPDG query="INSERT INTO test1 (id, name) VALUES (?, ?)" args="[{Name: Ordinal:1 Value:1} {Name: Ordinal:2 Value:Alice}]" duration=375 skip=true
time=2025-02-19T08:25:05.775+09:00 level=DEBUG msg=Conn.PrepareContext conn_id=GcehcYURvlj4lPDG query="INSERT INTO test1 (id, name) VALUES (?, ?)"
time=2025-02-19T08:25:05.776+09:00 level=INFO msg=Conn.PrepareContext conn_id=GcehcYURvlj4lPDG query="INSERT INTO test1 (id, name) VALUES (?, ?)" duration=1626541 stmt_id=nAPIE1kqEGIjsNpe
time=2025-02-19T08:25:05.776+09:00 level=DEBUG msg=Stmt.ExecContext conn_id=GcehcYURvlj4lPDG stmt_id=nAPIE1kqEGIjsNpe args="[{Name: Ordinal:1 Value:1} {Name: Ordinal:2 Value:Alice}]"
time=2025-02-19T08:25:05.777+09:00 level=INFO msg=Stmt.ExecContext conn_id=GcehcYURvlj4lPDG stmt_id=nAPIE1kqEGIjsNpe args="[{Name: Ordinal:1 Value:1} {Name: Ordinal:2 Value:Alice}]" duration=349958
time=2025-02-19T08:25:05.777+09:00 level=DEBUG msg=Stmt.Close conn_id=GcehcYURvlj4lPDG stmt_id=nAPIE1kqEGIjsNpe
time=2025-02-19T08:25:05.777+09:00 level=INFO msg=Stmt.Close conn_id=GcehcYURvlj4lPDG stmt_id=nAPIE1kqEGIjsNpe duration=4625
time=2025-02-19T08:25:05.777+09:00 level=DEBUG msg=Tx.Commit conn_id=GcehcYURvlj4lPDG tx_id=P_5GU9YZ66Q7cVCQ
time=2025-02-19T08:25:05.779+09:00 level=INFO msg=Tx.Commit conn_id=GcehcYURvlj4lPDG tx_id=P_5GU9YZ66Q7cVCQ duration=2369584
time=2025-02-19T08:25:05.779+09:00 level=DEBUG msg=Conn.QueryContext conn_id=GcehcYURvlj4lPDG query="SELECT * FROM test1" args=[] duration=348542
time=2025-02-19T08:25:05.779+09:00 level=DEBUG msg=Rows.Next conn_id=GcehcYURvlj4lPDG duration=13333 eof=false
time=2025-02-19T08:25:05.779+09:00 level=INFO msg=Record id=1 name=Alice
time=2025-02-19T08:25:05.779+09:00 level=DEBUG msg=Rows.Next conn_id=GcehcYURvlj4lPDG duration=83 eof=true
time=2025-02-19T08:25:05.779+09:00 level=DEBUG msg=Rows.Close conn_id=GcehcYURvlj4lPDG duration=125
time=2025-02-19T08:25:05.779+09:00 level=DEBUG msg=Conn.Close conn_id=GcehcYURvlj4lPDG
time=2025-02-19T08:25:05.779+09:00 level=INFO msg=Conn.Close conn_id=GcehcYURvlj4lPDG duration=18083
time=2025-08-06T23:24:18.087+09:00 level=INFO msg=Driver.OpenConnector dsn=root@tcp(localhost:3306)/app1 duration=10917 conn_id=OeV2RQ9XRdMCt45H
time=2025-08-06T23:24:18.087+09:00 level=INFO msg=Open driver=mysql dsn=root@tcp(localhost:3306)/app1 duration=470875
time=2025-08-06T23:24:18.089+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=2305125 error="driver: bad connection"
time=2025-08-06T23:24:18.089+09:00 level=ERROR msg=Connector.Connect duration=2338958 error="driver: bad connection"
time=2025-08-06T23:24:18.090+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=714542 error="driver: bad connection"
time=2025-08-06T23:24:18.090+09:00 level=ERROR msg=Connector.Connect duration=770750 error="driver: bad connection"
time=2025-08-06T23:24:18.091+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=683833 error="driver: bad connection"
time=2025-08-06T23:24:18.091+09:00 level=ERROR msg=Connector.Connect duration=693000 error="driver: bad connection"
time=2025-08-06T23:24:20.093+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=1196917 error="driver: bad connection"
time=2025-08-06T23:24:20.093+09:00 level=ERROR msg=Connector.Connect duration=1244834 error="driver: bad connection"
time=2025-08-06T23:24:20.094+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=1030584 error="driver: bad connection"
time=2025-08-06T23:24:20.094+09:00 level=ERROR msg=Connector.Connect duration=1042042 error="driver: bad connection"
time=2025-08-06T23:24:20.096+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=1188083 error="driver: bad connection"
time=2025-08-06T23:24:20.096+09:00 level=ERROR msg=Connector.Connect duration=1195750 error="driver: bad connection"
time=2025-08-06T23:24:22.097+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=843625 error="driver: bad connection"
time=2025-08-06T23:24:22.097+09:00 level=ERROR msg=Connector.Connect duration=874750 error="driver: bad connection"
time=2025-08-06T23:24:22.097+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=464875 error="driver: bad connection"
time=2025-08-06T23:24:22.097+09:00 level=ERROR msg=Connector.Connect duration=475041 error="driver: bad connection"
time=2025-08-06T23:24:22.097+09:00 level=ERROR msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=337459 error="driver: bad connection"
time=2025-08-06T23:24:22.097+09:00 level=ERROR msg=Connector.Connect duration=346666 error="driver: bad connection"
time=2025-08-06T23:24:24.103+09:00 level=INFO msg=Connector.Connect conn_id=OeV2RQ9XRdMCt45H duration=4660583
time=2025-08-06T23:24:24.103+09:00 level=INFO msg=Connector.Connect duration=4740458
time=2025-08-06T23:24:24.122+09:00 level=INFO msg=Conn.ExecContext conn_id=OeV2RQ9XRdMCt45H query="CREATE TABLE IF NOT EXISTS test1 (id INT PRIMARY KEY, name VARCHAR(255))" args=[] duration=17941958
time=2025-08-06T23:24:24.122+09:00 level=INFO msg=Conn.BeginTx conn_id=OeV2RQ9XRdMCt45H duration=244000 tx_id=2Z_gwjGK0ZsOhmKL
time=2025-08-06T23:24:24.122+09:00 level=INFO msg=Conn.ExecContext conn_id=OeV2RQ9XRdMCt45H query="INSERT INTO test1 (id, name) VALUES (?, ?)" args="[1,\"Alice\"]" duration=541 skip=true
time=2025-08-06T23:24:24.127+09:00 level=DEBUG msg=Stmt.ExecContext conn_id=OeV2RQ9XRdMCt45H stmt_id=Sh0A2dDAax1M8Fuj args="[1,\"Alice\"]" duration=610916
time=2025-08-06T23:24:24.127+09:00 level=DEBUG msg=Stmt.Close conn_id=OeV2RQ9XRdMCt45H stmt_id=Sh0A2dDAax1M8Fuj duration=7917
time=2025-08-06T23:24:24.128+09:00 level=INFO msg=Tx.Commit conn_id=OeV2RQ9XRdMCt45H tx_id=2Z_gwjGK0ZsOhmKL duration=1560625
time=2025-08-06T23:24:24.129+09:00 level=DEBUG msg=Conn.QueryContext conn_id=OeV2RQ9XRdMCt45H query="SELECT * FROM test1" args=[] duration=299875
time=2025-08-06T23:24:24.129+09:00 level=DEBUG msg=Rows.Next conn_id=OeV2RQ9XRdMCt45H duration=1458 eof=false
time=2025-08-06T23:24:24.129+09:00 level=INFO msg=Record id=1 name=Alice
time=2025-08-06T23:24:24.129+09:00 level=DEBUG msg=Rows.Next conn_id=OeV2RQ9XRdMCt45H duration=42 eof=true
time=2025-08-06T23:24:24.129+09:00 level=DEBUG msg=Rows.Close conn_id=OeV2RQ9XRdMCt45H duration=167
time=2025-08-06T23:24:24.129+09:00 level=INFO msg=Conn.Close conn_id=OeV2RQ9XRdMCt45H duration=20500
Loading
Loading