Improve logging

conn.go

@@ -140,17 +140,17 @@ func Connect(config ConnConfig) (c *Conn, err error) {
 		if err != nil {
 			return nil, err
 		}
-		c.logger.Debug("Using default User " + user.Username)
 		c.config.User = user.Username
+		c.logger.Debug("Using default connection config", "User", c.config.User)
 	}
 
 	if c.config.Port == 0 {
-		c.logger.Debug("Using default Port")
 		c.config.Port = 5432
+		c.logger.Debug("Using default connection config", "Port", c.config.Port)
 	}
 	if c.config.MsgBufSize == 0 {
-		c.logger.Debug("Using default MsgBufSize")
 		c.config.MsgBufSize = 1024
+		c.logger.Debug("Using default connection config", "MsgBufSize", c.config.MsgBufSize)
 	}
 
 	if c.config.Socket != "" {
@@ -279,13 +279,20 @@ func ParseURI(uri string) (ConnConfig, error) {
 // need to simultaneously store the entire result set in memory. It also means that
 // it is possible to process some rows and then for an error to occur. Callers
 // should be aware of this possibility.
-func (c *Conn) 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))
-		}
-	}()
+func (c *Conn) SelectFunc(sql string, onDataRow func(*DataRowReader) error, arguments ...interface{}) error {
+	startTime := time.Now()
+	err := c.selectFunc(sql, onDataRow, arguments...)
+	if err != nil {
+		c.logger.Error("SelectFunc", "sql", sql, "args", arguments, "error", err)
+		return err
+	}
 
+	endTime := time.Now()
+	c.logger.Info("SelectFunc", "sql", sql, "args", arguments, "time", endTime.Sub(startTime))
+	return nil
+}
+
+func (c *Conn) selectFunc(sql string, onDataRow func(*DataRowReader) error, arguments ...interface{}) (err error) {
 	var fields []FieldDescription
 
 	if ps, present := c.preparedStatements[sql]; present {
@@ -777,9 +784,14 @@ func (c *Conn) sendPreparedQuery(ps *preparedStatement, arguments ...interface{}
 // 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 *Conn) Execute(sql string, arguments ...interface{}) (commandTag CommandTag, err error) {
+	startTime := time.Now()
+
 	defer func() {
-		if err != nil {
-			c.logger.Error(fmt.Sprintf("Execute `%s` with %v failed: %v", sql, arguments, err))
+		if err == nil {
+			endTime := time.Now()
+			c.logger.Info("Execute", "sql", sql, "args", arguments, "time", endTime.Sub(startTime))
+		} else {
+			c.logger.Error("Execute", "sql", sql, "args", arguments, "error", err)
 		}
 	}()
 

examples/url_shortener/main.go

@@ -1,8 +1,8 @@
 package main
 
 import (
-	"fmt"
 	"github.com/JackC/pgx"
+	log "gopkg.in/inconshreveable/log15.v2"
 	"io/ioutil"
 	"net/http"
 	"os"
@@ -97,24 +97,29 @@ func urlHandler(w http.ResponseWriter, req *http.Request) {
 
 func main() {
 	var err error
-	connConfig := pgx.ConnConfig{
-		Host:     "127.0.0.1",
-		User:     "jack",
-		Password: "jack",
-		Database: "url_shortener"}
-	poolOptions := pgx.ConnPoolConfig{MaxConnections: 5, AfterConnect: afterConnect}
-	pool, err = pgx.NewConnPool(connConfig, poolOptions)
+	connPoolConfig := pgx.ConnPoolConfig{
+		ConnConfig: pgx.ConnConfig{
+			Host:     "127.0.0.1",
+			User:     "jack",
+			Password: "jack",
+			Database: "url_shortener",
+			Logger:   log.New("module", "pgx"),
+		},
+		MaxConnections: 5,
+		AfterConnect:   afterConnect,
+	}
+	pool, err = pgx.NewConnPool(connPoolConfig)
 	if err != nil {
-		fmt.Fprintf(os.Stderr, "Unable to create connection pool: %v\n", err)
+		log.Crit("Unable to create connection pool", "error", err)
 		os.Exit(1)
 	}
 
 	http.HandleFunc("/", urlHandler)
 
-	fmt.Println("Starting URL shortener on localhost:8080...")
+	log.Info("Starting URL shortener on localhost:8080")
 	err = http.ListenAndServe("localhost:8080", nil)
 	if err != nil {
-		fmt.Fprintf(os.Stderr, "Unable to start web server: %v\n", err)
+		log.Crit("Unable to start web server", "error", err)
 		os.Exit(1)
 	}
 }