From a1aa06c934f0164424953e7caa294561d1c9dda2 Mon Sep 17 00:00:00 2001 From: Jack Christensen Date: Wed, 16 Sep 2015 08:20:51 -0500 Subject: [PATCH] More efficient logging with log levels --- conn.go | 64 ++++++++++++++++++++++++++++++++++++---------------- conn_pool.go | 17 ++++++++++---- logger.go | 22 ++++++++++-------- query.go | 15 ++++++------ 4 files changed, 77 insertions(+), 41 deletions(-) diff --git a/conn.go b/conn.go index 487cb789..acf24a8a 100644 --- a/conn.go +++ b/conn.go @@ -34,6 +34,7 @@ type ConnConfig struct { UseFallbackTLS bool // Try FallbackTLSConfig if connecting with TLSConfig fails. Used for preferring TLS, but allowing unencrypted, or vice-versa FallbackTLSConfig *tls.Config // config for fallback TLS connection (only used if UseFallBackTLS is true)-- nil disables TLS Logger Logger + LogLevel int Dial DialFunc } @@ -56,6 +57,7 @@ type Conn struct { alive bool causeOfDeath error logger Logger + logLevel int mr msgReader fp *fastpath pgsql_af_inet byte @@ -111,10 +113,16 @@ func Connect(config ConnConfig) (c *Conn, err error) { c = new(Conn) c.config = config - if c.config.Logger != nil { - c.logger = c.config.Logger + + if c.config.LogLevel != 0 { + c.logLevel = c.config.LogLevel } else { - c.logger = dlogger + // Preserve pre-LogLevel behavior by defaulting to LogLevelDebug + c.logLevel = LogLevelDebug + } + c.logger = c.config.Logger + if c.logger == nil { + c.logLevel = LogLevelNone } if c.config.User == "" { @@ -123,12 +131,16 @@ func Connect(config ConnConfig) (c *Conn, err error) { return nil, err } c.config.User = user.Username - c.logger.Debug("Using default connection config", "User", c.config.User) + if c.logLevel >= LogLevelDebug { + c.logger.Debug("Using default connection config", "User", c.config.User) + } } if c.config.Port == 0 { c.config.Port = 5432 - c.logger.Debug("Using default connection config", "Port", c.config.Port) + if c.logLevel >= LogLevelDebug { + c.logger.Debug("Using default connection config", "Port", c.config.Port) + } } network := "tcp" @@ -159,17 +171,23 @@ func Connect(config ConnConfig) (c *Conn, err error) { } func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tls.Config) (err error) { - c.logger.Info(fmt.Sprintf("Dialing PostgreSQL server at %s address: %s", network, address)) + if c.logLevel >= LogLevelInfo { + c.logger.Info(fmt.Sprintf("Dialing PostgreSQL server at %s address: %s", network, address)) + } c.conn, err = c.config.Dial(network, address) if err != nil { - c.logger.Error(fmt.Sprintf("Connection failed: %v", err)) + if c.logLevel >= LogLevelError { + c.logger.Error(fmt.Sprintf("Connection failed: %v", err)) + } return err } defer func() { if c != nil && err != nil { c.conn.Close() c.alive = false - c.logger.Error(err.Error()) + if c.logLevel >= LogLevelError { + c.logger.Error(err.Error()) + } } }() @@ -179,9 +197,13 @@ func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tl c.lastActivityTime = time.Now() if tlsConfig != nil { - c.logger.Debug("Starting TLS handshake") + if c.logLevel >= LogLevelDebug { + c.logger.Debug("Starting TLS handshake") + } if err := c.startTLS(tlsConfig); err != nil { - c.logger.Error(fmt.Sprintf("TLS failed: %v", err)) + if c.logLevel >= LogLevelError { + c.logger.Error(fmt.Sprintf("TLS failed: %v", err)) + } return err } } @@ -215,7 +237,7 @@ func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tl } case readyForQuery: c.rxReadyForQuery(r) - if c.logger != dlogger { + if c.logLevel >= LogLevelInfo { c.logger = &connLogger{logger: c.logger, pid: c.Pid} c.logger.Info("Connection established") } @@ -292,7 +314,9 @@ func (c *Conn) Close() (err error) { _, err = c.conn.Write(wbuf.buf) c.die(errors.New("Closed")) - c.logger.Info("Closed connection") + if c.logLevel >= LogLevelInfo { + c.logger.Info("Closed connection") + } return err } @@ -460,11 +484,13 @@ func configSSL(sslmode string, cc *ConnConfig) error { // 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 *Conn) Prepare(name, sql string) (ps *PreparedStatement, err error) { - defer func() { - if err != nil { - c.logger.Error(fmt.Sprintf("Prepare `%s` as `%s` failed: %v", name, sql, err)) - } - }() + if c.logLevel >= LogLevelError { + defer func() { + if err != nil { + c.logger.Error(fmt.Sprintf("Prepare `%s` as `%s` failed: %v", name, sql, err)) + } + }() + } // parse wbuf := newWriteBuf(c, 'P') @@ -853,7 +879,7 @@ func (c *Conn) Exec(sql string, arguments ...interface{}) (commandTag CommandTag startTime := time.Now() c.lastActivityTime = startTime - if c.logger != dlogger { + if c.logLevel >= LogLevelError { defer func() { if err == nil { endTime := time.Now() @@ -929,7 +955,7 @@ func (c *Conn) rxMsg() (t byte, r *msgReader, err error) { c.lastActivityTime = time.Now() - if c.logger != dlogger { + if c.logLevel >= LogLevelTrace { c.logger.Debug("rxMsg", "Type", string(t), "Size", c.mr.msgBytesRemaining) } diff --git a/conn_pool.go b/conn_pool.go index cd8b7f63..ce11b499 100644 --- a/conn_pool.go +++ b/conn_pool.go @@ -19,6 +19,7 @@ type ConnPool struct { maxConnections int afterConnect func(*Conn) error logger Logger + logLevel int closed bool } @@ -42,10 +43,16 @@ func NewConnPool(config ConnPoolConfig) (p *ConnPool, err error) { } p.afterConnect = config.AfterConnect - if config.Logger != nil { - p.logger = config.Logger + + if config.LogLevel != 0 { + p.logLevel = config.LogLevel } else { - p.logger = &discardLogger{} + // Preserve pre-LogLevel behavior by defaulting to LogLevelDebug + p.logLevel = LogLevelDebug + } + p.logger = config.Logger + if p.logger == nil { + p.logLevel = LogLevelNone } p.allConnections = make([]*Conn, 0, p.maxConnections) @@ -92,7 +99,9 @@ func (p *ConnPool) Acquire() (c *Conn, err error) { // All connections are in use and we cannot create more if len(p.availableConnections) == 0 { - p.logger.Warn("All connections in pool are busy - waiting...") + if p.logLevel >= LogLevelWarn { + p.logger.Warn("All connections in pool are busy - waiting...") + } for len(p.availableConnections) == 0 { p.cond.Wait() } diff --git a/logger.go b/logger.go index d7c7d974..d59f6fd3 100644 --- a/logger.go +++ b/logger.go @@ -5,6 +5,18 @@ import ( "fmt" ) +// The values for log levels are chosen such that the zero value means that no +// log level was specified and we can default to LogLevelDebug to preserve +// the behavior that existed prior to log level introduction. +const ( + LogLevelTrace = 6 + LogLevelDebug = 5 + LogLevelInfo = 4 + LogLevelWarn = 3 + LogLevelError = 2 + LogLevelNone = 1 +) + // Logger is the interface used to get logging from pgx internals. // https://github.com/inconshreveable/log15 is the recommended logging package. // This logging interface was extracted from there. However, it should be simple @@ -17,16 +29,6 @@ type Logger interface { Error(msg string, ctx ...interface{}) } -type discardLogger struct{} - -// default discardLogger instance -var dlogger = &discardLogger{} - -func (l *discardLogger) Debug(msg string, ctx ...interface{}) {} -func (l *discardLogger) Info(msg string, ctx ...interface{}) {} -func (l *discardLogger) Warn(msg string, ctx ...interface{}) {} -func (l *discardLogger) Error(msg string, ctx ...interface{}) {} - type connLogger struct { logger Logger pid int32 diff --git a/query.go b/query.go index 0fd4d6ea..1810f305 100644 --- a/query.go +++ b/query.go @@ -52,6 +52,7 @@ type Rows struct { sql string args []interface{} logger Logger + logLevel int } func (rows *Rows) FieldDescriptions() []FieldDescription { @@ -70,14 +71,12 @@ func (rows *Rows) close() { rows.closed = true - if rows.logger == dlogger { - return - } - if rows.err == nil { - endTime := time.Now() - rows.logger.Info("Query", "sql", rows.sql, "args", logQueryArgs(rows.args), "time", endTime.Sub(rows.startTime), "rowCount", rows.rowCount) - } else { + if rows.logLevel >= LogLevelInfo { + endTime := time.Now() + rows.logger.Info("Query", "sql", rows.sql, "args", logQueryArgs(rows.args), "time", endTime.Sub(rows.startTime), "rowCount", rows.rowCount) + } + } else if rows.logLevel >= LogLevelError { rows.logger.Error("Query", "sql", rows.sql, "args", logQueryArgs(rows.args)) } } @@ -420,7 +419,7 @@ func (rows *Rows) Values() ([]interface{}, error) { // from Query and handle it in *Rows. func (c *Conn) Query(sql string, args ...interface{}) (*Rows, error) { c.lastActivityTime = time.Now() - rows := &Rows{conn: c, startTime: c.lastActivityTime, sql: sql, args: args, logger: c.logger} + rows := &Rows{conn: c, startTime: c.lastActivityTime, sql: sql, args: args, logger: c.logger, logLevel: c.logLevel} ps, ok := c.preparedStatements[sql] if !ok {