Added log adapter for logrus

Also changed standard logger interface to take a map instead of varargs for
extra data.

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)

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})
 			}
 		}
 

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

conn_test.go

@@ -1741,15 +1741,15 @@ func TestCatchSimultaneousConnectionQueryAndExec(t *testing.T) {
 type testLog struct {
 	lvl  pgx.LogLevel
 	msg  string
-	ctx []interface{}
+	data map[string]interface{}
 }
 
 type testLogger struct {
 	logs []testLog
 }
 
-func (l *testLogger) Log(level pgx.LogLevel, msg string, ctx ...interface{}) {
+func (l *testLogger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) {
-	l.logs = append(l.logs, testLog{lvl: level, msg: msg, ctx: ctx})
+	l.logs = append(l.logs, testLog{lvl: level, msg: msg, data: data})
 }
 
 func TestSetLogger(t *testing.T) {

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
+that satisfies this interface. Set LogLevel to control logging verbosity.
-verbosity.
+Adapters for github.com/inconshreveable/log15, github.com/Sirupsen/logrus, and
+the testing log are provided in the log directory.
 */
 package pgx

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)...)
 	}
 }

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)
+	}
+}

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{}) {
+func (l *Logger) Log(level pgx.LogLevel, msg string, data map[string]interface{}) {
-	l.l.Log(level, msg, ctx)
+	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...)
 }

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 a message at the given level with data key/value pairs. data may be nil.
-	Log(level LogLevel, msg string, ctx ...interface{})
+	Log(level LogLevel, msg string, data map[string]interface{})
 }
 
 // LogLevelFromString converts log level string to constant

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 {

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})
 		}
 	}
 

stdlib/sql_test.go

@@ -367,15 +367,15 @@ func TestConnQuery(t *testing.T) {
 type testLog struct {
 	lvl  pgx.LogLevel
 	msg  string
-	ctx []interface{}
+	data map[string]interface{}
 }
 
 type testLogger struct {
 	logs []testLog
 }
 
-func (l *testLogger) Log(lvl pgx.LogLevel, msg string, ctx ...interface{}) {
+func (l *testLogger) Log(lvl pgx.LogLevel, msg string, data map[string]interface{}) {
-	l.logs = append(l.logs, testLog{lvl: lvl, msg: msg, ctx: ctx})
+	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)
 	}
 }

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