GOCBC-91: beef up logging API and implementation

Modifications to the logging API:
- Logger interface contains a Log() method which contains a caller level
  and a verbosity level
- Default logger now uses the 'log' package and logs to standard error
- Logging wrt scheduling/receiving responses is now its own level,
  instead of logDebugf, reducing the logging output by far.
- VerboseStdLogger enables all levels; DefaultStdLogger enables all
  levels except scheduling.

Change-Id: I03fe831affcc6d15444f3d0587f83b5ae71d09ed
Reviewed-on: http://review.couchbase.org/58851
Reviewed-by: Brett Lawson <brett19@gmail.com>
Tested-by: Mark Nunberg <mark.nunberg@couchbase.com>

gocbcore/agent_test.go

@@ -689,6 +689,7 @@ func TestMemcachedBucket(t *testing.T) {
 }
 
 func TestMain(m *testing.M) {
+	SetLogger(DefaultStdOutLogger())
 	flag.Parse()
 	mpath, err := gocbmock.GetMockPath()
 	if err != nil {

gocbcore/logging.go

@@ -2,35 +2,105 @@ package gocbcore
 
 import (
 	"fmt"
+	"log"
+	"os"
 )
 
+type LogLevel int
+
+// **VOLATILE** (subject to change)
+// Various logging levels (or subsystems) which can categorize the message.
+// Currently these are ordered in decreasing severity.
+const (
+	LogError LogLevel = iota
+	LogWarn
+	LogInfo
+	LogDebug
+	LogTrace
+	LogSched
+	LogMaxVerbosity
+)
+
+// **VOLATILE**
+// Logging interface. You can either use one of the default loggers
+// (DefaultStdioLogger(), VerboseStdioLogger()) or implement your own.
 type Logger interface {
-	Output(s string) error
+	// Outputs logging information:
+	// level is the verbosity level
+	// offset is the position within the calling stack from which the message
+	// originated. This is useful for contextual loggers which retrieve file/line
+	// information.
+	Log(level LogLevel, offset int, format string, v ...interface{}) error
 }
 
 type defaultLogger struct {
+	Level    LogLevel
+	GoLogger *log.Logger
 }
 
-func (l *defaultLogger) Output(s string) error {
-	_, err := fmt.Println(s)
-	return err
+func (l *defaultLogger) Log(level LogLevel, offset int, format string, v ...interface{}) error {
+	if level > l.Level {
+		return nil
+	}
+	s := fmt.Sprintf(format, v...)
+	l.GoLogger.Output(offset+1, s)
+	return nil
 }
 
 var (
-	globalDefaultLogger defaultLogger
-	globalLogger        Logger
+	globalDefaultLogger = defaultLogger{
+		GoLogger: log.New(os.Stderr, "GOCB ", log.Lmicroseconds|log.Lshortfile), Level: LogDebug,
+	}
+
+	globalVerboseLogger = defaultLogger{
+		GoLogger: globalDefaultLogger.GoLogger, Level: LogMaxVerbosity,
+	}
+
+	globalLogger Logger
 )
 
+// **DEPRECATED** (Use DefaultStdioLogger() instead)
+// Returns the default logger. This actually logs to stderr rather than
+// stdout. Use DefaultStdioLogger which has a correct name, since the
+// "standard" logger logs to stderr, rather than stdout.
 func DefaultStdOutLogger() Logger {
 	return &globalDefaultLogger
 }
 
+// **UNCOMMITTED**
+// Gets the default standard I/O logger. You can then make gocbcore log by using
+// the following idiom:
+// gocbcore.SetLogger(gocbcore.DefaultStdioLogger())
+func DefaultStdioLogger() Logger {
+	return &globalDefaultLogger
+}
+
+// **UNCOMMITTED**
+// This is a more verbose level of DefaultStdioLogger(). Messages pertaining to the
+// scheduling of ordinary commands (and their responses) will also be emitted
+// gocbcore.SetLogger(gocbcore.VerboseStdioLogger())
+func VerboseStdioLogger() Logger {
+	return &globalVerboseLogger
+}
+
+// **UNCOMMITTED**
+// Sets the logger to be used by the library. A logger can be obtained via the
+// DefaultStdioLogger() or VerboseStdioLogger() functions. You can also implement
+// your own logger using the volatile Logger interface.
 func SetLogger(logger Logger) {
 	globalLogger = logger
 }
 
-func logDebugf(format string, v ...interface{}) {
+func logExf(level LogLevel, offset int, format string, v ...interface{}) {
 	if globalLogger != nil {
-		globalLogger.Output(fmt.Sprintf("DEBUG: "+format, v...))
+		globalLogger.Log(level, offset+1, format, v...)
 	}
 }
+
+func logDebugf(format string, v ...interface{}) {
+	logExf(LogDebug, 2, format, v...)
+}
+
+func logSchedf(format string, v ...interface{}) {
+	logExf(LogSched, 2, format, v...)
+}

gocbcore/memdpipeline.go

@@ -160,7 +160,7 @@ func (s *memdPipeline) resolveRequest(resp *memdResponse) {
 	}
 
 	// Call the requests callback handler...  Ignore Status field for incoming requests.
-	logDebugf("Dispatching response callback.")
+	logSchedf("Dispatching response callback. OP=0x%x. Opaque=%d", resp.Opcode, resp.Opaque)
 	if resp.Magic == ReqMagic {
 		req.Callback(resp, nil)
 	} else {
@@ -182,8 +182,7 @@ func (pipeline *memdPipeline) ioLoop() {
 				killSig <- true
 				break
 			}
-
-			logDebugf("Got response to resolve.")
+			logSchedf("Resolving response OP=0x%x. Opaque=%d", resp.Opcode, resp.Opaque)
 			pipeline.resolveRequest(resp)
 		}
 	}()
@@ -193,7 +192,7 @@ func (pipeline *memdPipeline) ioLoop() {
 	for {
 		select {
 		case req := <-pipeline.queue.reqsCh:
-			logDebugf("Got a request to dispatch.")
+			logSchedf("Dispatching request OP=0x%x. Opaque=%d.", req.Opcode, req.Opaque)
 			err := pipeline.dispatchRequest(req)
 			if err != nil {
 				// Ensure that the connection gets fully closed

gocbcore/memdqueue.go

@@ -59,7 +59,7 @@ func (s *memdQueue) QueueRequest(req *memdQRequest) bool {
 		panic("Request was dispatched while already queued somewhere.")
 	}
 
-	logDebugf("Writing request to queue!")
+	logSchedf("Writing request to queue!")
 
 	// Try to write the request to the queue, if the queue is full,
 	//   we immediately fail the request with a queueOverflow error.