diff --git a/bench_test.go b/bench_test.go index 91c73293..d3525df5 100644 --- a/bench_test.go +++ b/bench_test.go @@ -179,7 +179,7 @@ func BenchmarkSelectWithoutLogging(b *testing.B) { type discardLogger struct{} -func (dl discardLogger) Log(level pgx.LogLevel, msg string, ctx ...interface{}) {} +func (dl discardLogger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) {} func BenchmarkSelectWithLoggingTraceDiscard(b *testing.B) { conn := mustConnect(b, *defaultConnConfig) diff --git a/conn.go b/conn.go index 81a38df9..bca9f6d8 100644 --- a/conn.go +++ b/conn.go @@ -222,14 +222,14 @@ func connect(config ConnConfig, connInfo *pgtype.ConnInfo) (c *Conn, err error) } c.config.User = user.Username if c.shouldLog(LogLevelDebug) { - c.log(LogLevelDebug, "Using default connection config", "User", c.config.User) + c.log(LogLevelDebug, "Using default connection config", map[string]interface{}{"User": c.config.User}) } } if c.config.Port == 0 { c.config.Port = 5432 if c.shouldLog(LogLevelDebug) { - c.log(LogLevelDebug, "Using default connection config", "Port", c.config.Port) + c.log(LogLevelDebug, "Using default connection config", map[string]interface{}{"Port": c.config.Port}) } } @@ -239,19 +239,19 @@ func connect(config ConnConfig, connInfo *pgtype.ConnInfo) (c *Conn, err error) } if c.shouldLog(LogLevelInfo) { - c.log(LogLevelInfo, fmt.Sprintf("Dialing PostgreSQL server at %s address: %s", network, address)) + c.log(LogLevelInfo, "Dialing PostgreSQL server", map[string]interface{}{"network": network, "address": address}) } err = c.connect(config, network, address, config.TLSConfig) if err != nil && config.UseFallbackTLS { if c.shouldLog(LogLevelInfo) { - c.log(LogLevelInfo, fmt.Sprintf("Connect with TLSConfig failed, trying FallbackTLSConfig: %v", err)) + c.log(LogLevelInfo, "connect with TLSConfig failed, trying FallbackTLSConfig", map[string]interface{}{"err": err}) } err = c.connect(config, network, address, config.FallbackTLSConfig) } if err != nil { if c.shouldLog(LogLevelError) { - c.log(LogLevelError, fmt.Sprintf("Connect failed: %v", err)) + c.log(LogLevelError, "connect failed", map[string]interface{}{"err": err}) } return nil, err } @@ -282,7 +282,7 @@ func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tl if tlsConfig != nil { if c.shouldLog(LogLevelDebug) { - c.log(LogLevelDebug, "Starting TLS handshake") + c.log(LogLevelDebug, "starting TLS handshake", nil) } if err := c.startTLS(tlsConfig); err != nil { return err @@ -334,7 +334,7 @@ func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tl case *pgproto3.ReadyForQuery: c.rxReadyForQuery(msg) if c.shouldLog(LogLevelInfo) { - c.log(LogLevelInfo, "Connection established") + c.log(LogLevelInfo, "connection established", nil) } // Replication connections can't execute the queries to @@ -414,25 +414,25 @@ func (c *Conn) Close() (err error) { c.conn.Close() c.die(errors.New("Closed")) if c.shouldLog(LogLevelInfo) { - c.log(LogLevelInfo, "Closed connection") + c.log(LogLevelInfo, "closed connection", nil) } }() err = c.conn.SetDeadline(time.Time{}) if err != nil && c.shouldLog(LogLevelWarn) { - c.log(LogLevelWarn, "Failed to clear deadlines to send close message", "err", err) + c.log(LogLevelWarn, "failed to clear deadlines to send close message", map[string]interface{}{"err": err}) return err } _, err = c.conn.Write([]byte{'X', 0, 0, 0, 4}) if err != nil && c.shouldLog(LogLevelWarn) { - c.log(LogLevelWarn, "Failed to send terminate message", "err", err) + c.log(LogLevelWarn, "failed to send terminate message", map[string]interface{}{"err": err}) return err } err = c.conn.SetReadDeadline(time.Now().Add(5 * time.Second)) if err != nil && c.shouldLog(LogLevelWarn) { - c.log(LogLevelWarn, "Failed to set read deadline to finish closing", "err", err) + c.log(LogLevelWarn, "failed to set read deadline to finish closing", map[string]interface{}{"err": err}) return err } @@ -701,7 +701,7 @@ func (c *Conn) prepareEx(name, sql string, opts *PrepareExOptions) (ps *Prepared if c.shouldLog(LogLevelError) { defer func() { if err != nil { - c.log(LogLevelError, fmt.Sprintf("Prepare `%s` as `%s` failed: %v", name, sql, err)) + c.log(LogLevelError, "prepareEx failed", map[string]interface{}{"err": err, "name": name, "sql": sql}) } }() } @@ -1213,12 +1213,15 @@ func (c *Conn) shouldLog(lvl int) bool { return c.logger != nil && c.logLevel >= lvl } -func (c *Conn) log(lvl LogLevel, msg string, ctx ...interface{}) { +func (c *Conn) log(lvl LogLevel, msg string, data map[string]interface{}) { + if data == nil { + data = map[string]interface{}{} + } if c.pid != 0 { - ctx = append(ctx, "pid", c.PID) + data["pid"] = c.PID } - c.logger.Log(lvl, msg, ctx...) + c.logger.Log(lvl, msg, data) } // SetLogger replaces the current logger and returns the previous logger. @@ -1327,11 +1330,11 @@ func (c *Conn) ExecEx(ctx context.Context, sql string, options *QueryExOptions, if err == nil { if c.shouldLog(LogLevelInfo) { endTime := time.Now() - c.log(LogLevelInfo, "Exec", "sql", sql, "args", logQueryArgs(arguments), "time", endTime.Sub(startTime), "commandTag", commandTag) + c.log(LogLevelInfo, "Exec", map[string]interface{}{"sql": sql, "args": logQueryArgs(arguments), "time": endTime.Sub(startTime), "commandTag": commandTag}) } } else { if c.shouldLog(LogLevelError) { - c.log(LogLevelError, "Exec", "sql", sql, "args", logQueryArgs(arguments), "error", err) + c.log(LogLevelError, "Exec", map[string]interface{}{"sql": sql, "args": logQueryArgs(arguments), "err": err}) } } diff --git a/conn_pool.go b/conn_pool.go index 8703d7fa..7bc022d0 100644 --- a/conn_pool.go +++ b/conn_pool.go @@ -164,7 +164,7 @@ func (p *ConnPool) acquire(deadline *time.Time) (*Conn, error) { } // All connections are in use and we cannot create more if p.logLevel >= LogLevelWarn { - p.logger.Log(LogLevelWarn, "All connections in pool are busy - waiting...") + p.logger.Log(LogLevelWarn, "waiting for available connection", nil) } // Wait until there is an available connection OR room to create a new connection diff --git a/conn_test.go b/conn_test.go index 8f47d995..f887e030 100644 --- a/conn_test.go +++ b/conn_test.go @@ -1739,17 +1739,17 @@ func TestCatchSimultaneousConnectionQueryAndExec(t *testing.T) { } type testLog struct { - lvl pgx.LogLevel - msg string - ctx []interface{} + lvl pgx.LogLevel + msg string + data map[string]interface{} } type testLogger struct { logs []testLog } -func (l *testLogger) Log(level pgx.LogLevel, msg string, ctx ...interface{}) { - l.logs = append(l.logs, testLog{lvl: level, msg: msg, ctx: ctx}) +func (l *testLogger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) { + l.logs = append(l.logs, testLog{lvl: level, msg: msg, data: data}) } func TestSetLogger(t *testing.T) { diff --git a/doc.go b/doc.go index 0921242a..a0f0bd72 100644 --- a/doc.go +++ b/doc.go @@ -239,7 +239,8 @@ connection. Logging pgx defines a simple logger interface. Connections optionally accept a logger -that satisfies this interface. Set LogLevel to control logging -verbosity. +that satisfies this interface. Set LogLevel to control logging verbosity. +Adapters for github.com/inconshreveable/log15, github.com/Sirupsen/logrus, and +the testing log are provided in the log directory. */ package pgx diff --git a/log/log15adapter/adapter.go b/log/log15adapter/adapter.go index 55d1b79f..8623a380 100644 --- a/log/log15adapter/adapter.go +++ b/log/log15adapter/adapter.go @@ -24,19 +24,24 @@ func NewLogger(l Log15Logger) *Logger { return &Logger{l: l} } -func (l *Logger) Log(level pgx.LogLevel, msg string, ctx ...interface{}) { +func (l *Logger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) { + logArgs := make([]interface{}, 0, len(data)) + for k, v := range data { + logArgs = append(logArgs, k, v) + } + switch level { case pgx.LogLevelTrace: - l.l.Debug(msg, append(ctx, "PGX_LOG_LEVEL", level)...) + l.l.Debug(msg, append(logArgs, "PGX_LOG_LEVEL", level)...) case pgx.LogLevelDebug: - l.l.Debug(msg, ctx...) + l.l.Debug(msg, logArgs...) case pgx.LogLevelInfo: - l.l.Info(msg, ctx...) + l.l.Info(msg, logArgs...) case pgx.LogLevelWarn: - l.l.Warn(msg, ctx...) + l.l.Warn(msg, logArgs...) case pgx.LogLevelError: - l.l.Error(msg, ctx...) + l.l.Error(msg, logArgs...) default: - l.l.Error(msg, append(ctx, "INVALID_PGX_LOG_LEVEL", level)...) + l.l.Error(msg, append(logArgs, "INVALID_PGX_LOG_LEVEL", level)...) } } diff --git a/log/logrusadapter/adapter.go b/log/logrusadapter/adapter.go new file mode 100644 index 00000000..6084c36c --- /dev/null +++ b/log/logrusadapter/adapter.go @@ -0,0 +1,40 @@ +// Package logrusadapter provides a logger that writes to a github.com/Sirupsen/logrus.Logger +// log. +package logrusadapter + +import ( + "github.com/Sirupsen/logrus" + "github.com/jackc/pgx" +) + +type Logger struct { + l *logrus.Logger +} + +func NewLogger(l *logrus.Logger) *Logger { + return &Logger{l: l} +} + +func (l *Logger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) { + var logger logrus.FieldLogger + if data != nil { + logger = l.l.WithFields(data) + } else { + logger = l.l + } + + switch level { + case pgx.LogLevelTrace: + logger.WithField("PGX_LOG_LEVEL", level).Debug(msg) + case pgx.LogLevelDebug: + logger.Debug(msg) + case pgx.LogLevelInfo: + logger.Info(msg) + case pgx.LogLevelWarn: + logger.Warn(msg) + case pgx.LogLevelError: + logger.Error(msg) + default: + logger.WithField("INVALID_PGX_LOG_LEVEL", level).Error(msg) + } +} diff --git a/log/testingadapter/adapter.go b/log/testingadapter/adapter.go index f042c4f1..6c9cde83 100644 --- a/log/testingadapter/adapter.go +++ b/log/testingadapter/adapter.go @@ -3,6 +3,8 @@ package testingadapter import ( + "fmt" + "github.com/jackc/pgx" ) @@ -20,6 +22,11 @@ func NewLogger(l TestingLogger) *Logger { return &Logger{l: l} } -func (l *Logger) Log(level pgx.LogLevel, msg string, ctx ...interface{}) { - l.l.Log(level, msg, ctx) +func (l *Logger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) { + logArgs := make([]interface{}, 0, 2+len(data)) + logArgs = append(logArgs, level, msg) + for k, v := range data { + logArgs = append(logArgs, fmt.Sprintf("%s=%v", k, v)) + } + l.l.Log(logArgs...) } diff --git a/logger.go b/logger.go index f1b85322..c2df1d7d 100644 --- a/logger.go +++ b/logger.go @@ -42,8 +42,8 @@ func (ll LogLevel) String() string { // Logger is the interface used to get logging from pgx internals. type Logger interface { - // Log a message at the given level with context key/value pairs - Log(level LogLevel, msg string, ctx ...interface{}) + // Log a message at the given level with data key/value pairs. data may be nil. + Log(level LogLevel, msg string, data map[string]interface{}) } // LogLevelFromString converts log level string to constant diff --git a/query.go b/query.go index 04a87043..3d081714 100644 --- a/query.go +++ b/query.go @@ -78,10 +78,10 @@ func (rows *Rows) Close() { if rows.err == nil { if rows.conn.shouldLog(LogLevelInfo) { endTime := time.Now() - rows.conn.log(LogLevelInfo, "Query", "sql", rows.sql, "args", logQueryArgs(rows.args), "time", endTime.Sub(rows.startTime), "rowCount", rows.rowCount) + rows.conn.log(LogLevelInfo, "Query", map[string]interface{}{"sql": rows.sql, "args": logQueryArgs(rows.args), "time": endTime.Sub(rows.startTime), "rowCount": rows.rowCount}) } } else if rows.conn.shouldLog(LogLevelError) { - rows.conn.log(LogLevelError, "Query", "sql", rows.sql, "args", logQueryArgs(rows.args)) + rows.conn.log(LogLevelError, "Query", map[string]interface{}{"sql": rows.sql, "args": logQueryArgs(rows.args)}) } if rows.afterClose != nil { diff --git a/replication.go b/replication.go index ea768961..594944e0 100644 --- a/replication.go +++ b/replication.go @@ -215,12 +215,12 @@ func (rc *ReplicationConn) readReplicationMessage() (r *ReplicationMessage, err case *pgproto3.NoticeResponse: pgError := rc.c.rxErrorResponse((*pgproto3.ErrorResponse)(msg)) if rc.c.shouldLog(LogLevelInfo) { - rc.c.log(LogLevelInfo, pgError.Error()) + rc.c.log(LogLevelInfo, pgError.Error(), nil) } case *pgproto3.ErrorResponse: err = rc.c.rxErrorResponse(msg) if rc.c.shouldLog(LogLevelError) { - rc.c.log(LogLevelError, err.Error()) + rc.c.log(LogLevelError, err.Error(), nil) } return case *pgproto3.CopyBothResponse: @@ -258,12 +258,12 @@ func (rc *ReplicationConn) readReplicationMessage() (r *ReplicationMessage, err return &ReplicationMessage{ServerHeartbeat: h}, nil default: if rc.c.shouldLog(LogLevelError) { - rc.c.log(LogLevelError, "Unexpected data playload message type %v", msgType) + rc.c.log(LogLevelError, "Unexpected data playload message type", map[string]interface{}{"type": msgType}) } } default: if rc.c.shouldLog(LogLevelError) { - rc.c.log(LogLevelError, "Unexpected replication message type %T", msg) + rc.c.log(LogLevelError, "Unexpected replication message type", map[string]interface{}{"type": msg}) } } return @@ -421,7 +421,7 @@ func (rc *ReplicationConn) StartReplication(slotName string, startLsn uint64, ti r, err = rc.WaitForReplicationMessage(ctx) if err != nil && r != nil { if rc.c.shouldLog(LogLevelError) { - rc.c.log(LogLevelError, "Unxpected replication message %v", r) + rc.c.log(LogLevelError, "Unexpected replication message", map[string]interface{}{"msg": r, "err": err}) } } diff --git a/stdlib/sql_test.go b/stdlib/sql_test.go index dadafd41..ba74560d 100644 --- a/stdlib/sql_test.go +++ b/stdlib/sql_test.go @@ -365,17 +365,17 @@ func TestConnQuery(t *testing.T) { } type testLog struct { - lvl pgx.LogLevel - msg string - ctx []interface{} + lvl pgx.LogLevel + msg string + data map[string]interface{} } type testLogger struct { logs []testLog } -func (l *testLogger) Log(lvl pgx.LogLevel, msg string, ctx ...interface{}) { - l.logs = append(l.logs, testLog{lvl: lvl, msg: msg, ctx: ctx}) +func (l *testLogger) Log(lvl pgx.LogLevel, msg string, data map[string]interface{}) { + l.logs = append(l.logs, testLog{lvl: lvl, msg: msg, data: data}) } func TestConnQueryLog(t *testing.T) { @@ -416,7 +416,7 @@ func TestConnQueryLog(t *testing.T) { t.Errorf("Expected to log Query, but got %v", l) } - if !(l.ctx[0] == "sql" && l.ctx[1] == "select 1") { + if l.data["sql"] != "select 1" { t.Errorf("Expected to log Query with sql 'select 1', but got %v", l) } } diff --git a/v3.md b/v3.md index 2946bcf0..72110888 100644 --- a/v3.md +++ b/v3.md @@ -50,8 +50,6 @@ Remove names from prepared statements - use database/sql style objects Better way of handling text/binary protocol choice than pgx.DefaultTypeFormats or manually editing a PreparedStatement. Possibly an optional part of preparing a statement is specifying the format and/or a decoder. Or maybe it is part of a QueryEx call... Could be very interesting to make encoding and decoding possible without being a method of the type. This could drastically clean up those huge type switches. -msgReader cleanup - Make easier / possible to mock Conn or ConnPool (https://github.com/jackc/pgx/pull/162) Every field that should not be set by user should be replaced by accessor method (only ones left are Conn.RuntimeParams and Conn.PgTypes) @@ -68,3 +66,5 @@ something like: select array[1,2,3], array[4,5,6,7] Reconsider synonym types like varchar/text and numeric/decimal. + +integrate logging and context - should be able to replace logger via context OR inject params into log from context