Add trace logging

bench_test.go

@@ -273,6 +273,23 @@ func BenchmarkSelectWithoutLogging(b *testing.B) {
 	benchmarkSelectWithLog(b, conn)
 }
 
+func BenchmarkSelectWithLoggingTraceWithLog15(b *testing.B) {
+	connConfig := *defaultConnConfig
+
+	logger := log.New()
+	lvl, err := log.LvlFromString("debug")
+	if err != nil {
+		b.Fatal(err)
+	}
+	logger.SetHandler(log.LvlFilterHandler(lvl, log.DiscardHandler()))
+	connConfig.Logger = logger
+	connConfig.LogLevel = pgx.LogLevelTrace
+	conn := mustConnect(b, connConfig)
+	defer closeConn(b, conn)
+
+	benchmarkSelectWithLog(b, conn)
+}
+
 func BenchmarkSelectWithLoggingDebugWithLog15(b *testing.B) {
 	connConfig := *defaultConnConfig
 
@@ -283,6 +300,7 @@ func BenchmarkSelectWithLoggingDebugWithLog15(b *testing.B) {
 	}
 	logger.SetHandler(log.LvlFilterHandler(lvl, log.DiscardHandler()))
 	connConfig.Logger = logger
+	connConfig.LogLevel = pgx.LogLevelDebug
 	conn := mustConnect(b, connConfig)
 	defer closeConn(b, conn)
 
@@ -299,6 +317,7 @@ func BenchmarkSelectWithLoggingInfoWithLog15(b *testing.B) {
 	}
 	logger.SetHandler(log.LvlFilterHandler(lvl, log.DiscardHandler()))
 	connConfig.Logger = logger
+	connConfig.LogLevel = pgx.LogLevelInfo
 	conn := mustConnect(b, connConfig)
 	defer closeConn(b, conn)
 
@@ -315,6 +334,7 @@ func BenchmarkSelectWithLoggingErrorWithLog15(b *testing.B) {
 	}
 	logger.SetHandler(log.LvlFilterHandler(lvl, log.DiscardHandler()))
 	connConfig.Logger = logger
+	connConfig.LogLevel = pgx.LogLevelError
 	conn := mustConnect(b, connConfig)
 	defer closeConn(b, conn)
 

conn.go

@@ -124,6 +124,8 @@ func Connect(config ConnConfig) (c *Conn, err error) {
 	if c.logger == nil {
 		c.logLevel = LogLevelNone
 	}
+	c.mr.logger = c.logger
+	c.mr.logLevel = c.logLevel
 
 	if c.config.User == "" {
 		user, err := user.Current()
@@ -956,7 +958,7 @@ func (c *Conn) rxMsg() (t byte, r *msgReader, err error) {
 	c.lastActivityTime = time.Now()
 
 	if c.logLevel >= LogLevelTrace {
-		c.logger.Debug("rxMsg", "Type", string(t), "Size", c.mr.msgBytesRemaining)
+		c.logger.Debug("rxMsg", "type", string(t), "msgBytesRemaining", c.mr.msgBytesRemaining)
 	}
 
 	return t, &c.mr, err

doc.go

@@ -192,7 +192,8 @@ Logging
 
 pgx defines a simple logger interface. Connections optionally accept a logger
 that satisfies this interface. The log15 package
-(http://gopkg.in/inconshreveable/log15.v2) satisfies this interface
-and it is simple to define adapters for other loggers.
+(http://gopkg.in/inconshreveable/log15.v2) satisfies this interface and it is
+simple to define adapters for other loggers. Set LogLevel to control logging
+verbosity.
 */
 package pgx

msg_reader.go

@@ -14,6 +14,8 @@ type msgReader struct {
 	buf               [128]byte
 	msgBytesRemaining int32
 	err               error
+	logger            Logger
+	logLevel          int
 }
 
 // Err returns any error that the msgReader has experienced
@@ -23,6 +25,9 @@ func (r *msgReader) Err() error {
 
 // fatal tells r that a Fatal error has occurred
 func (r *msgReader) fatal(err error) {
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.fatal", "error", err, "msgBytesRemaining", r.msgBytesRemaining)
+	}
 	r.err = err
 }
 
@@ -33,6 +38,10 @@ func (r *msgReader) rxMsg() (t byte, err error) {
 	}
 
 	if r.msgBytesRemaining > 0 {
+		if r.logLevel >= LogLevelTrace {
+			r.logger.Debug("msgReader.rxMsg discarding unread previous message", "msgBytesRemaining", r.msgBytesRemaining)
+		}
+
 		io.CopyN(ioutil.Discard, r.reader, int64(r.msgBytesRemaining))
 	}
 
@@ -59,6 +68,10 @@ func (r *msgReader) readByte() byte {
 		return 0
 	}
 
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readByte", "value", b, "byteAsString", string(b), "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
 	return b
 }
 
@@ -80,7 +93,13 @@ func (r *msgReader) readInt16() int16 {
 		return 0
 	}
 
-	return int16(binary.BigEndian.Uint16(b))
+	n := int16(binary.BigEndian.Uint16(b))
+
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readInt16", "value", n, "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
+	return n
 }
 
 func (r *msgReader) readInt32() int32 {
@@ -101,7 +120,13 @@ func (r *msgReader) readInt32() int32 {
 		return 0
 	}
 
-	return int32(binary.BigEndian.Uint32(b))
+	n := int32(binary.BigEndian.Uint32(b))
+
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readInt32", "value", n, "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
+	return n
 }
 
 func (r *msgReader) readInt64() int64 {
@@ -122,7 +147,13 @@ func (r *msgReader) readInt64() int64 {
 		return 0
 	}
 
-	return int64(binary.BigEndian.Uint64(b))
+	n := int64(binary.BigEndian.Uint64(b))
+
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readInt64", "value", n, "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
+	return n
 }
 
 func (r *msgReader) readOid() Oid {
@@ -147,7 +178,13 @@ func (r *msgReader) readCString() string {
 		return ""
 	}
 
-	return string(b[0 : len(b)-1])
+	s := string(b[0 : len(b)-1])
+
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readCString", "value", s, "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
+	return s
 }
 
 // readString reads count bytes and returns as string
@@ -175,7 +212,13 @@ func (r *msgReader) readString(count int32) string {
 		return ""
 	}
 
-	return string(b)
+	s := string(b)
+
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readString", "value", s, "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
+	return s
 }
 
 // readBytes reads count bytes and returns as []byte
@@ -198,5 +241,9 @@ func (r *msgReader) readBytes(count int32) []byte {
 		return nil
 	}
 
+	if r.logLevel >= LogLevelTrace {
+		r.logger.Debug("msgReader.readBytes", "value", b, "msgBytesRemaining", r.msgBytesRemaining)
+	}
+
 	return b
 }