devicemapper: change LogInit and move all callbacks to pkg

LogInit used to act as a manual way of registering the *necessary*
pkg/devicemapper logging callbacks. In addition, it was used to split up
the logic of pkg/devicemapper into daemon/graphdriver/devmapper (such
that some things were logged from libdm).

The manual aspect of this API was completely non-sensical and was just
begging for incorrect usage of pkg/devicemapper, so remove that semantic
and always register our own libdm callbacks.

In addition, recombine the split out logging callbacks into
pkg/devicemapper so that the default logger is local to the library and
also shown to be the recommended logger. This makes the code
substantially easier to read. Also the new DefaultLogger now has
configurable upper-bound for the log level, which allows for dynamically
changing the logging level.

Signed-off-by: Aleksa Sarai <asarai@suse.de>

daemon/graphdriver/devmapper/deviceset.go

@@ -35,17 +35,13 @@ import (
 )
 
 var (
-	defaultDataLoopbackSize     int64  = 100 * 1024 * 1024 * 1024
-	defaultMetaDataLoopbackSize int64  = 2 * 1024 * 1024 * 1024
-	defaultBaseFsSize           uint64 = 10 * 1024 * 1024 * 1024
-	defaultThinpBlockSize       uint32 = 128 // 64K = 128 512b sectors
-	defaultUdevSyncOverride            = false
-	maxDeviceID                        = 0xffffff // 24 bit, pool limit
-	deviceIDMapSz                      = (maxDeviceID + 1) / 8
-	// We retry device removal so many a times that even error messages
-	// will fill up console during normal operation. So only log Fatal
-	// messages by default.
-	logLevel                            = devicemapper.LogLevelFatal
+	defaultDataLoopbackSize      int64  = 100 * 1024 * 1024 * 1024
+	defaultMetaDataLoopbackSize  int64  = 2 * 1024 * 1024 * 1024
+	defaultBaseFsSize            uint64 = 10 * 1024 * 1024 * 1024
+	defaultThinpBlockSize        uint32 = 128 // 64K = 128 512b sectors
+	defaultUdevSyncOverride             = false
+	maxDeviceID                         = 0xffffff // 24 bit, pool limit
+	deviceIDMapSz                       = (maxDeviceID + 1) / 8
 	driverDeferredRemovalSupport        = false
 	enableDeferredRemoval               = false
 	enableDeferredDeletion              = false
@@ -1273,26 +1269,6 @@ func setCloseOnExec(name string) {
 	}
 }
 
-// DMLog implements logging using DevMapperLogger interface.
-func (devices *DeviceSet) DMLog(level int, file string, line int, dmError int, message string) {
-	// By default libdm sends us all the messages including debug ones.
-	// We need to filter out messages here and figure out which one
-	// should be printed.
-	if level > logLevel {
-		return
-	}
-
-	// FIXME(vbatts) push this back into ./pkg/devicemapper/
-	if level <= devicemapper.LogLevelErr {
-		logrus.Errorf("libdevmapper(%d): %s:%d (%d) %s", level, file, line, dmError, message)
-	} else if level <= devicemapper.LogLevelInfo {
-		logrus.Infof("libdevmapper(%d): %s:%d (%d) %s", level, file, line, dmError, message)
-	} else {
-		// FIXME(vbatts) push this back into ./pkg/devicemapper/
-		logrus.Debugf("libdevmapper(%d): %s:%d (%d) %s", level, file, line, dmError, message)
-	}
-}
-
 func major(device uint64) uint64 {
 	return (device >> 8) & 0xfff
 }
@@ -1690,9 +1666,6 @@ func (devices *DeviceSet) enableDeferredRemovalDeletion() error {
 }
 
 func (devices *DeviceSet) initDevmapper(doInit bool) (retErr error) {
-	// give ourselves to libdm as a log handler
-	devicemapper.LogInit(devices)
-
 	if err := devices.enableDeferredRemovalDeletion(); err != nil {
 		return err
 	}

pkg/devicemapper/devmapper.go

@@ -13,11 +13,6 @@ import (
 	"github.com/Sirupsen/logrus"
 )
 
-// DevmapperLogger defines methods for logging with devicemapper.
-type DevmapperLogger interface {
-	DMLog(level int, file string, line int, dmError int, message string)
-}
-
 const (
 	deviceCreate TaskType = iota
 	deviceReload
@@ -264,14 +259,6 @@ func UdevWait(cookie *uint) error {
 	return nil
 }
 
-var dmLogger DevmapperLogger
-
-// LogInit initializes the logger for the device mapper library.
-func LogInit(logger DevmapperLogger) {
-	dmLogger = logger
-	LogWithErrnoInit()
-}
-
 // SetDevDir sets the dev folder for the device mapper library (usually /dev).
 func SetDevDir(dir string) error {
 	if res := DmSetDevDir(dir); res != 1 {

pkg/devicemapper/devmapper_log.go

@@ -5,17 +5,45 @@ package devicemapper
 import "C"
 
 import (
+	"fmt"
 	"strings"
+
+	"github.com/Sirupsen/logrus"
 )
 
+// DevmapperLogger defines methods required to register as a callback for
+// logging events recieved from devicemapper. Note that devicemapper will send
+// *all* logs regardless to callbacks (including debug logs) so it's
+// recommended to not spam the console with the outputs.
+type DevmapperLogger interface {
+	// DMLog is the logging callback containing all of the information from
+	// devicemapper. The interface is identical to the C libdm counterpart.
+	DMLog(level int, file string, line int, dmError int, message string)
+}
+
+// dmLogger is the current logger in use that is being forwarded our messages.
+var dmLogger DevmapperLogger
+
+// LogInit changes the logging callback called after processing libdm logs for
+// error message information. The default logger simply forwards all logs to
+// logrus. Calling LogInit(nil) disables the calling of callbacks.
+func LogInit(logger DevmapperLogger) {
+	dmLogger = logger
+}
+
 // Due to the way cgo works this has to be in a separate file, as devmapper.go has
 // definitions in the cgo block, which is incompatible with using "//export"
 
-// DevmapperLogCallback exports the devmapper log callback for cgo.
+// DevmapperLogCallback exports the devmapper log callback for cgo. Note that
+// because we are using callbacks, this function will be called for *every* log
+// in libdm (even debug ones because there's no way of setting the verbosity
+// level for an external logging callback).
 //export DevmapperLogCallback
-func DevmapperLogCallback(level C.int, file *C.char, line C.int, dmErrnoOrClass C.int, message *C.char) {
+func DevmapperLogCallback(level C.int, file *C.char, line, dmErrnoOrClass C.int, message *C.char) {
 	msg := C.GoString(message)
-	if level < 7 {
+
+	// Track what errno libdm saw, because the library only gives us 0 or 1.
+	if level < LogLevelDebug {
 		if strings.Contains(msg, "busy") {
 			dmSawBusy = true
 		}
@@ -33,3 +61,61 @@ func DevmapperLogCallback(level C.int, file *C.char, line C.int, dmErrnoOrClass
 		dmLogger.DMLog(int(level), C.GoString(file), int(line), int(dmErrnoOrClass), msg)
 	}
 }
+
+// DefaultLogger is the default logger used by pkg/devicemapper. It forwards
+// all logs that are of higher or equal priority to the given level to the
+// corresponding logrus level.
+type DefaultLogger struct {
+	// Level corresponds to the highest libdm level that will be forwarded to
+	// logrus. In order to change this, register a new DefaultLogger.
+	Level int
+}
+
+// DMLog is the logging callback containing all of the information from
+// devicemapper. The interface is identical to the C libdm counterpart.
+func (l DefaultLogger) DMLog(level int, file string, line, dmError int, message string) {
+	if int(level) <= l.Level {
+		// Forward the log to the correct logrus level, if allowed by dmLogLevel.
+		logMsg := fmt.Sprintf("libdevmapper(%d): %s:%d (%d) %s", level, file, line, dmError, message)
+		switch level {
+		case LogLevelFatal, LogLevelErr:
+			logrus.Error(logMsg)
+		case LogLevelWarn:
+			logrus.Warn(logMsg)
+		case LogLevelNotice, LogLevelInfo:
+			logrus.Info(logMsg)
+		case LogLevelDebug:
+			logrus.Debug(logMsg)
+		default:
+			// Don't drop any "unknown" levels.
+			logrus.Info(logMsg)
+		}
+	}
+}
+
+// registerLogCallback registers our own logging callback function for libdm
+// (which is DevmapperLogCallback).
+//
+// Because libdm only gives us {0,1} error codes we need to parse the logs
+// produced by libdm (to set dmSawBusy and so on). Note that by registering a
+// callback using DevmapperLogCallback, libdm will no longer output logs to
+// stderr so we have to log everything ourselves. None of this handling is
+// optional because we depend on log callbacks to parse the logs, and if we
+// don't forward the log information we'll be in a lot of trouble when
+// debugging things.
+func registerLogCallback() {
+	LogWithErrnoInit()
+}
+
+func init() {
+	// Use the default logger by default. We only allow LogLevelFatal by
+	// default, because internally we mask a lot of libdm errors by retrying
+	// and similar tricks. Also, libdm is very chatty and we don't want to
+	// worry users for no reason.
+	dmLogger = DefaultLogger{
+		Level: LogLevelFatal,
+	}
+
+	// Register as early as possible so we don't miss anything.
+	registerLogCallback()
+}