Add basic logging to pgx

fixes #21

README.md

@@ -139,6 +139,12 @@ arrays (or any types) differently can easily override the default transcoding
 (so even using a strict with value and null fields would simply be a matter of
 changing transcoders).
 
+### Logging
+
+Pgx defines the pgx.Logger interface. A value that satisfies this interface
+used as part of ConnectionOptions or ConnectionPoolOptions to enable logging
+of pgx activities.
+
 ## Testing
 
 Pgx supports multiple connection and authentication types. Setting up a test

connection.go

@@ -27,6 +27,7 @@ type ConnectionParameters struct {
 	Password   string
 	MsgBufSize int         // Size of work buffer used for transcoding messages. For optimal performance, it should be large enough to store a single row from any result set. Default: 1024
 	TLSConfig  *tls.Config // config for TLS connection -- nil disables TLS
+	Logger     Logger
 }
 
 // Connection is a PostgreSQL connection handle. It is not safe for concurrent usage.
@@ -46,6 +47,7 @@ type Connection struct {
 	notifications      []*Notification
 	alive              bool
 	causeOfDeath       error
+	logger             Logger
 }
 
 type preparedStatement struct {
@@ -94,21 +96,33 @@ func Connect(parameters ConnectionParameters) (c *Connection, err error) {
 	c = new(Connection)
 
 	c.parameters = parameters
+	if c.parameters.Logger != nil {
+		c.logger = c.parameters.Logger
+	} else {
+		c.logger = nullLogger("null")
+	}
+
 	if c.parameters.Port == 0 {
+		c.logger.Debug("Using default Port")
 		c.parameters.Port = 5432
 	}
 	if c.parameters.MsgBufSize == 0 {
+		c.logger.Debug("Using default MsgBufSize")
 		c.parameters.MsgBufSize = 1024
 	}
 
 	if c.parameters.Socket != "" {
+		c.logger.Info(fmt.Sprintf("Dialing PostgreSQL server at socket: %s", c.parameters.Socket))
 		c.conn, err = net.Dial("unix", c.parameters.Socket)
 		if err != nil {
+			c.logger.Error(fmt.Sprintf("Connection failed: %v", err))
 			return nil, err
 		}
 	} else if c.parameters.Host != "" {
+		c.logger.Info(fmt.Sprintf("Dialing PostgreSQL server at host: %s:%d", c.parameters.Host, c.parameters.Port))
 		c.conn, err = net.Dial("tcp", fmt.Sprintf("%s:%d", c.parameters.Host, c.parameters.Port))
 		if err != nil {
+			c.logger.Error(fmt.Sprintf("Connection failed: %v", err))
 			return nil, err
 		}
 	}
@@ -116,6 +130,7 @@ func Connect(parameters ConnectionParameters) (c *Connection, err error) {
 		if c != nil && err != nil {
 			c.conn.Close()
 			c.alive = false
+			c.logger.Error(err.Error())
 		}
 	}()
 
@@ -126,7 +141,9 @@ func Connect(parameters ConnectionParameters) (c *Connection, err error) {
 	c.alive = true
 
 	if parameters.TLSConfig != nil {
+		c.logger.Debug("Starting TLS handshake")
 		if err = c.startTLS(); err != nil {
+			c.logger.Error(fmt.Sprintf("TLS failed: %v", err))
 			return
 		}
 	}
@@ -155,6 +172,8 @@ func Connect(parameters ConnectionParameters) (c *Connection, err error) {
 				}
 			case readyForQuery:
 				c.rxReadyForQuery(r)
+				c.logger = newPidLogger(c.Pid, c.logger)
+				c.logger.Info("Connection established")
 				return c, nil
 			default:
 				if err = c.processContextFreeMsg(t, r); err != nil {
@@ -170,6 +189,7 @@ func Connect(parameters ConnectionParameters) (c *Connection, err error) {
 func (c *Connection) Close() (err error) {
 	err = c.txMsg('X', c.getBuf(), true)
 	c.die(errors.New("Closed"))
+	c.logger.Info("Closed connection")
 	return err
 }
 
@@ -183,6 +203,12 @@ func (c *Connection) Close() (err error) {
 // it is possible to process some rows and then for an error to occur. Callers
 // should be aware of this possibility.
 func (c *Connection) SelectFunc(sql string, onDataRow func(*DataRowReader) error, arguments ...interface{}) (err error) {
+	defer func() {
+		if err != nil {
+			c.logger.Error(fmt.Sprintf("SelectFunc `%s` with %v failed: %v", sql, arguments, err))
+		}
+	}()
+
 	var fields []FieldDescription
 
 	if ps, present := c.preparedStatements[sql]; present {
@@ -298,6 +324,12 @@ func (c *Connection) SelectValue(sql string, arguments ...interface{}) (v interf
 // Returns a UnexpectedColumnCountError if exactly one column is not found
 // Returns a NotSingleRowError if exactly one row is not found
 func (c *Connection) SelectValueTo(w io.Writer, sql string, arguments ...interface{}) (err error) {
+	defer func() {
+		if err != nil {
+			c.logger.Error(fmt.Sprintf("SelectValueTo `%s` with %v failed: %v", sql, arguments, err))
+		}
+	}()
+
 	if err = c.sendQuery(sql, arguments...); err != nil {
 		return
 	}
@@ -413,6 +445,12 @@ func (c *Connection) SelectValues(sql string, arguments ...interface{}) (values
 // Prepare creates a prepared statement with name and sql. sql can contain placeholders
 // for bound parameters. These placeholders are referenced positional as $1, $2, etc.
 func (c *Connection) Prepare(name, sql string) (err error) {
+	defer func() {
+		if err != nil {
+			c.logger.Error(fmt.Sprintf("Prepare `%s` as `%s` failed: %v", name, sql, err))
+		}
+	}()
+
 	// parse
 	buf := c.getBuf()
 	w := newMessageWriter(buf)
@@ -638,6 +676,12 @@ func (c *Connection) sendPreparedQuery(ps *preparedStatement, arguments ...inter
 // arguments will be sanitized before being interpolated into sql strings. arguments
 // should be referenced positionally from the sql string as $1, $2, etc.
 func (c *Connection) Execute(sql string, arguments ...interface{}) (commandTag string, err error) {
+	defer func() {
+		if err != nil {
+			c.logger.Error(fmt.Sprintf("Execute `%s` with %v failed: %v", sql, arguments, err))
+		}
+	}()
+
 	if err = c.sendQuery(sql, arguments...); err != nil {
 		return
 	}
@@ -978,6 +1022,7 @@ func (c *Connection) txPasswordMessage(password string) (err error) {
 func (c *Connection) getBuf() *bytes.Buffer {
 	c.buf.Reset()
 	if cap(c.buf.Bytes()) > c.bufSize {
+		c.logger.Debug(fmt.Sprintf("c.buf (%d) is larger than c.bufSize (%d) -- resetting", cap(c.buf.Bytes()), c.bufSize))
 		c.buf = bytes.NewBuffer(make([]byte, 0, c.bufSize))
 	}
 	return c.buf

connection_pool.go

@@ -8,6 +8,7 @@ import (
 type ConnectionPoolOptions struct {
 	MaxConnections int // max simultaneous connections to use
 	AfterConnect   func(*Connection) error
+	Logger         Logger
 }
 
 type ConnectionPool struct {
@@ -17,6 +18,7 @@ type ConnectionPool struct {
 	parameters           ConnectionParameters // parameters used when establishing connection
 	maxConnections       int
 	afterConnect         func(*Connection) error
+	logger               Logger
 }
 
 type ConnectionPoolStat struct {
@@ -32,6 +34,11 @@ func NewConnectionPool(parameters ConnectionParameters, options ConnectionPoolOp
 	p.parameters = parameters
 	p.maxConnections = options.MaxConnections
 	p.afterConnect = options.AfterConnect
+	if options.Logger != nil {
+		p.logger = options.Logger
+	} else {
+		p.logger = nullLogger("null")
+	}
 
 	p.allConnections = make([]*Connection, 0, p.maxConnections)
 	p.availableConnections = make([]*Connection, 0, p.maxConnections)
@@ -72,9 +79,12 @@ func (p *ConnectionPool) Acquire() (c *Connection, err error) {
 	}
 
 	// All connections are in use and we cannot create more
+	if len(p.availableConnections) == 0 {
+		p.logger.Warning("All connections in pool are busy - waiting...")
 		for len(p.availableConnections) == 0 {
 			p.cond.Wait()
 		}
+	}
 
 	c = p.availableConnections[len(p.availableConnections)-1]
 	p.availableConnections = p.availableConnections[:len(p.availableConnections)-1]

logger.go

@@ -0,0 +1,34 @@
+package pgx
+
+import (
+	"strconv"
+)
+
+type Logger interface {
+	Error(msg string)
+	Warning(msg string)
+	Info(msg string)
+	Debug(msg string)
+}
+
+type nullLogger string
+
+func (l nullLogger) Error(msg string)   {}
+func (l nullLogger) Warning(msg string) {}
+func (l nullLogger) Info(msg string)    {}
+func (l nullLogger) Debug(msg string)   {}
+
+type pidLogger struct {
+	prefix     string
+	baseLogger Logger
+}
+
+func newPidLogger(pid int32, baseLogger Logger) *pidLogger {
+	prefix := "(" + strconv.FormatInt(int64(pid), 10) + ") "
+	return &pidLogger{prefix: prefix, baseLogger: baseLogger}
+}
+
+func (l *pidLogger) Error(msg string)   { l.baseLogger.Error(l.prefix + msg) }
+func (l *pidLogger) Warning(msg string) { l.baseLogger.Warning(l.prefix + msg) }
+func (l *pidLogger) Info(msg string)    { l.baseLogger.Info(l.prefix + msg) }
+func (l *pidLogger) Debug(msg string)   { l.baseLogger.Debug(l.prefix + msg) }