Merge pull request #33845 from cyphar/devicemapper-show-me-your-logs

devicemapper: rework logging and add --storage-opt dm.libdm_log_level

daemon/graphdriver/devmapper/deviceset.go

@@ -34,17 +34,13 @@ import (
 )
 
 var (
-	defaultDataLoopbackSize     int64  = 100 * 1024 * 1024 * 1024
+	defaultDataLoopbackSize      int64  = 100 * 1024 * 1024 * 1024
-	defaultMetaDataLoopbackSize int64  = 2 * 1024 * 1024 * 1024
+	defaultMetaDataLoopbackSize  int64  = 2 * 1024 * 1024 * 1024
-	defaultBaseFsSize           uint64 = 10 * 1024 * 1024 * 1024
+	defaultBaseFsSize            uint64 = 10 * 1024 * 1024 * 1024
-	defaultThinpBlockSize       uint32 = 128 // 64K = 128 512b sectors
+	defaultThinpBlockSize        uint32 = 128 // 64K = 128 512b sectors
-	defaultUdevSyncOverride            = false
+	defaultUdevSyncOverride             = false
-	maxDeviceID                        = 0xffffff // 24 bit, pool limit
+	maxDeviceID                         = 0xffffff // 24 bit, pool limit
-	deviceIDMapSz                      = (maxDeviceID + 1) / 8
+	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
 	driverDeferredRemovalSupport        = false
 	enableDeferredRemoval               = false
 	enableDeferredDeletion              = false
@@ -1272,26 +1268,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
 }
@@ -1689,9 +1665,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
 	}
@@ -2804,6 +2777,18 @@ func NewDeviceSet(root string, doInit bool, options []string, uidMaps, gidMaps [
 				return nil, errors.New("dm.thinp_autoextend_threshold must be greater than 0 and less than 100")
 			}
 			lvmSetupConfig.AutoExtendThreshold = per
+		case "dm.libdm_log_level":
+			level, err := strconv.ParseInt(val, 10, 32)
+			if err != nil {
+				return nil, errors.Wrapf(err, "could not parse `dm.libdm_log_level=%s`", val)
+			}
+			if level < devicemapper.LogLevelFatal || level > devicemapper.LogLevelDebug {
+				return nil, errors.Errorf("dm.libdm_log_level must be in range [%d,%d]", devicemapper.LogLevelFatal, devicemapper.LogLevelDebug)
+			}
+			// Register a new logging callback with the specified level.
+			devicemapper.LogInit(devicemapper.DefaultLogger{
+				Level: int(level),
+			})
 		default:
 			return nil, fmt.Errorf("devmapper: Unknown option %s\n", key)
 		}

pkg/devicemapper/devmapper.go

@@ -13,11 +13,6 @@ import (
 	"golang.org/x/sys/unix"
 )
 
-// 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,19 +259,6 @@ func UdevWait(cookie *uint) error {
 	return nil
 }
 
-// LogInitVerbose is an interface to initialize the verbose logger for the device mapper library.
-func LogInitVerbose(level int) {
-	DmLogInitVerbose(level)
-}
-
-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()
+}

pkg/devicemapper/devmapper_wrapper.go

@@ -4,6 +4,7 @@ package devicemapper
 
 /*
 #cgo LDFLAGS: -L. -ldevmapper
+#define _GNU_SOURCE
 #include <libdevmapper.h>
 #include <linux/fs.h>   // FIXME: present only for BLKGETSIZE64, maybe we can remove it?
 
@@ -12,19 +13,20 @@ extern void DevmapperLogCallback(int level, char *file, int line, int dm_errno_o
 
 static void	log_cb(int level, const char *file, int line, int dm_errno_or_class, const char *f, ...)
 {
-  char buffer[256];
+	char *buffer = NULL;
-  va_list ap;
+	va_list ap;
 
-  va_start(ap, f);
+	va_start(ap, f);
-  vsnprintf(buffer, 256, f, ap);
+	vasprintf(&buffer, f, ap);
-  va_end(ap);
+	va_end(ap);
 
-  DevmapperLogCallback(level, (char *)file, line, dm_errno_or_class, buffer);
+	DevmapperLogCallback(level, (char *)file, line, dm_errno_or_class, buffer);
+	free(buffer);
 }
 
 static void	log_with_errno_init()
 {
-  dm_log_with_errno_init(log_cb);
+	dm_log_with_errno_init(log_cb);
 }
 */
 import "C"
@@ -56,7 +58,6 @@ const (
 var (
 	DmGetLibraryVersion       = dmGetLibraryVersionFct
 	DmGetNextTarget           = dmGetNextTargetFct
-	DmLogInitVerbose          = dmLogInitVerboseFct
 	DmSetDevDir               = dmSetDevDirFct
 	DmTaskAddTarget           = dmTaskAddTargetFct
 	DmTaskCreate              = dmTaskCreateFct
@@ -226,10 +227,6 @@ func dmCookieSupportedFct() int {
 	return int(C.dm_cookie_supported())
 }
 
-func dmLogInitVerboseFct(level int) {
-	C.dm_log_init_verbose(C.int(level))
-}
-
 func logWithErrnoInitFct() {
 	C.log_with_errno_init()
 }