Context Logger (denisenkom#691)

* Pass contexts to checkBadConn

* Add ContextLogger interface and optional implementation

* ContextLogger unit tests and renaming

* Add LogRetry config param

* Categorize uncategorized log messages

* Normalize Logger's use of prefixes

* Make log_test compatible with Go 1.8 - 1.12

* Synchronize testLogger to prevent post-test logging

* Show actual caller of testLogger Print functions

* Remove t.Helper calls because go 1.8 doesn't support them

* Update TestTypeSizesFromQuery to defer StopLogging

bad_server_test.go

@@ -42,7 +42,9 @@ func testBadServer(t *testing.T, handler func(net.Conn)) {
 		handler(conn)
 		_ = conn.Close()
 	}()
-	SetLogger(testLogger{t})
+	tl := testLogger{t: t}
+	defer tl.StopLogging()
+	SetLogger(&tl)
 	testConnectionBad(t, fmt.Sprintf("host=%s;port=%d;log=255", addr.IP.String(), addr.Port))
 }
 

bulkcopy.go

@@ -12,6 +12,7 @@ import (
 	"time"
 
 	"github.com/denisenkom/go-mssqldb/internal/decimal"
+	"github.com/denisenkom/go-mssqldb/msdsn"
 )
 
 type Bulk struct {
@@ -86,7 +87,7 @@ func (b *Bulk) sendBulkCommand(ctx context.Context) (err error) {
 				bulkCol.ti.TypeId = typeBigVarBin
 			}
 			b.bulkColumns = append(b.bulkColumns, *bulkCol)
-			b.dlogf("Adding column %s %s %#x", colname, bulkCol.ColName, bulkCol.ti.TypeId)
+			b.dlogf(ctx, "Adding column %s %s %#x", colname, bulkCol.ColName, bulkCol.ti.TypeId)
 		} else {
 			return fmt.Errorf("column %s does not exist in destination table %s", colname, b.tablename)
 		}
@@ -138,7 +139,7 @@ func (b *Bulk) sendBulkCommand(ctx context.Context) (err error) {
 	if err != nil {
 		return fmt.Errorf("Prepare failed: %s", err.Error())
 	}
-	b.dlogf(query)
+	b.dlogf(ctx, query)
 
 	_, err = stmt.(*Stmt).ExecContext(ctx, nil)
 	if err != nil {
@@ -211,7 +212,7 @@ func (b *Bulk) makeRowData(row []interface{}) ([]byte, error) {
 		}
 	}
 
-	b.dlogf("row[%d] %s\n", b.numRows, logcol.String())
+	b.dlogf(b.ctx, "row[%d] %s", b.numRows, logcol.String())
 
 	return buf.Bytes(), nil
 }
@@ -238,7 +239,7 @@ func (b *Bulk) Done() (rowcount int64, err error) {
 	reader := startReading(b.cn.sess, b.ctx, outputs{})
 	err = reader.iterateResponse()
 	if err != nil {
-		return 0, b.cn.checkBadConn(err, false)
+		return 0, b.cn.checkBadConn(b.ctx, err, false)
 	}
 
 	return reader.rowCount, nil
@@ -300,7 +301,7 @@ func (b *Bulk) getMetadata(ctx context.Context) (err error) {
 
 	if b.Debug {
 		for _, col := range b.metadata {
-			b.dlogf("col: %s typeId: %#x size: %d scale: %d prec: %d flags: %d lcid: %#x\n",
+			b.dlogf(ctx, "col: %s typeId: %#x size: %d scale: %d prec: %d flags: %d lcid: %#x",
 				col.ColName, col.ti.TypeId, col.ti.Size, col.ti.Scale, col.ti.Prec,
 				col.Flags, col.ti.Collation.LcidAndFlags)
 		}
@@ -590,8 +591,8 @@ func (b *Bulk) makeParam(val DataValue, col columnStruct) (res param, err error)
 
 }
 
-func (b *Bulk) dlogf(format string, v ...interface{}) {
+func (b *Bulk) dlogf(ctx context.Context, format string, v ...interface{}) {
 	if b.Debug {
-		b.cn.sess.log.Printf(format, v...)
+		b.cn.sess.logger.Log(ctx, msdsn.LogDebug, fmt.Sprintf(format, v...))
 	}
 }

bulkcopy_test.go

@@ -94,8 +94,9 @@ func TestBulkcopy(t *testing.T) {
 		values[i] = val.in
 	}
 
-	pool := open(t)
+	pool, logger := open(t)
 	defer pool.Close()
+	defer logger.StopLogging()
 
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()

log.go

@@ -1,30 +1,71 @@
 package mssql
 
 import (
-	"log"
+	"context"
+
+	"github.com/denisenkom/go-mssqldb/msdsn"
+)
+
+const (
+	logErrors      = uint64(msdsn.LogErrors)
+	logMessages    = uint64(msdsn.LogMessages)
+	logRows        = uint64(msdsn.LogRows)
+	logSQL         = uint64(msdsn.LogSQL)
+	logParams      = uint64(msdsn.LogParams)
+	logTransaction = uint64(msdsn.LogTransaction)
+	logDebug       = uint64(msdsn.LogDebug)
+	logRetries     = uint64(msdsn.LogRetries)
 )
 
+// Logger is an interface you can implement to have the go-msqldb
+// driver automatically log detailed information on your behalf
 type Logger interface {
 	Printf(format string, v ...interface{})
 	Println(v ...interface{})
 }
 
+// ContextLogger is an interface that provides more information
+// than Logger and lets you log messages yourself. This gives you
+// more information to log (e.g. trace IDs in the context), more
+// control over the logging activity (e.g. log it, trace it, or
+// log and trace it, depending on the class of message), and lets
+// you log in exactly the format you want.
+type ContextLogger interface {
+	Log(ctx context.Context, category msdsn.Log, msg string)
+}
+
+// optionalLogger implements the ContextLogger interface with
+// a default "do nothing" behavior that can be overridden by an
+// optional ContextLogger supplied by the user.
 type optionalLogger struct {
-	logger Logger
+	logger ContextLogger
 }
 
-func (o optionalLogger) Printf(format string, v ...interface{}) {
-	if o.logger != nil {
-		o.logger.Printf(format, v...)
-	} else {
-		log.Printf(format, v...)
+// Log does nothing unless the user has specified an optional
+// ContextLogger to override the "do nothing" default behavior.
+func (o optionalLogger) Log(ctx context.Context, category msdsn.Log, msg string) {
+	if nil != o.logger {
+		o.logger.Log(ctx, category, msg)
 	}
 }
 
-func (o optionalLogger) Println(v ...interface{}) {
-	if o.logger != nil {
-		o.logger.Println(v...)
-	} else {
-		log.Println(v...)
+// loggerAdapter converts Logger interfaces into ContextLogger
+// interfaces. It provides backwards compatibility.
+type loggerAdapter struct {
+	logger Logger
+}
+
+// Log passes the message to the underlying Logger interface's
+// Println function, emulating the orignal Logger behavior.
+func (la loggerAdapter) Log(_ context.Context, category msdsn.Log, msg string) {
+
+	// Add prefix for certain categories
+	switch category {
+	case msdsn.LogErrors:
+		msg = "ERROR: " + msg
+	case msdsn.LogRetries:
+		msg = "RETRY: " + msg
 	}
+
+	la.logger.Println(msg)
 }

log_go113_test.go

@@ -0,0 +1,12 @@
+// +build go1.13
+
+package mssql
+
+import (
+	"io"
+	"log"
+)
+
+func currentLogWriter() io.Writer {
+	return log.Writer()
+}

log_go113pre_test.go

@@ -0,0 +1,14 @@
+// +build !go1.13
+
+package mssql
+
+import (
+	"io"
+	"os"
+)
+
+func currentLogWriter() io.Writer {
+	// There is no function for getting the current writer in versions of
+	// Go older than 1.13, so we just return the default writer.
+	return os.Stderr
+}