From 63328c6882c3d1f54c66499ef9963adfbf1883f0 Mon Sep 17 00:00:00 2001 From: Aleksa Sarai Date: Wed, 28 Jun 2017 01:44:31 +1000 Subject: [PATCH 1/4] devicemapper: remove 256 character limit of libdm logs This limit is unecessary and can lead to the truncation of long libdm logs (which is quite annoying). Fixes: b440ec013 ("device-mapper: Move all devicemapper spew to log through utils.Debugf().") Signed-off-by: Aleksa Sarai --- pkg/devicemapper/devmapper_wrapper.go | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/pkg/devicemapper/devmapper_wrapper.go b/pkg/devicemapper/devmapper_wrapper.go index 4f270fba0b..cdd9db95ff 100644 --- a/pkg/devicemapper/devmapper_wrapper.go +++ b/pkg/devicemapper/devmapper_wrapper.go @@ -4,6 +4,7 @@ package devicemapper /* #cgo LDFLAGS: -L. -ldevmapper +#define _GNU_SOURCE #include #include // 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]; - va_list ap; + char *buffer = NULL; + va_list ap; - va_start(ap, f); - vsnprintf(buffer, 256, f, ap); - va_end(ap); + va_start(ap, f); + vasprintf(&buffer, f, 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" From c654147f0635736fff0035ecdfa53a41c7fad0d0 Mon Sep 17 00:00:00 2001 From: Aleksa Sarai Date: Wed, 28 Jun 2017 01:45:24 +1000 Subject: [PATCH 2/4] devicemapper: actually remove DmLogInitVerbose e07d3cd9a ("devmapper: Fix libdm logging") removed all of the callers of DmLogInitVerbose, but we still kept around the wrapper. However, the libdm dm_log_init_verbose API changes the verbosity of the *default* libdm logger. Because pkg/devicemapper internally *relies* on using logging callbacks to understand what errors were encountered by libdm, this wrapper is useless (it only makes sense for the default logger which we do not user). Any user not inside Docker of this function almost certainly was not using this API correctly, because pkg/devicemapper will misbehave if our logging callbacks were not registered. Signed-off-by: Aleksa Sarai --- pkg/devicemapper/devmapper.go | 5 ----- pkg/devicemapper/devmapper_wrapper.go | 5 ----- 2 files changed, 10 deletions(-) diff --git a/pkg/devicemapper/devmapper.go b/pkg/devicemapper/devmapper.go index 73433c0e5a..8f35914366 100644 --- a/pkg/devicemapper/devmapper.go +++ b/pkg/devicemapper/devmapper.go @@ -264,11 +264,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. diff --git a/pkg/devicemapper/devmapper_wrapper.go b/pkg/devicemapper/devmapper_wrapper.go index cdd9db95ff..0fb70fe5b3 100644 --- a/pkg/devicemapper/devmapper_wrapper.go +++ b/pkg/devicemapper/devmapper_wrapper.go @@ -58,7 +58,6 @@ const ( var ( DmGetLibraryVersion = dmGetLibraryVersionFct DmGetNextTarget = dmGetNextTargetFct - DmLogInitVerbose = dmLogInitVerboseFct DmSetDevDir = dmSetDevDirFct DmTaskAddTarget = dmTaskAddTargetFct DmTaskCreate = dmTaskCreateFct @@ -228,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() } From cfd39e8d6d79eee8a71fbe6820dd67babf05d951 Mon Sep 17 00:00:00 2001 From: Aleksa Sarai Date: Wed, 28 Jun 2017 01:46:47 +1000 Subject: [PATCH 3/4] 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 --- daemon/graphdriver/devmapper/deviceset.go | 41 ++-------- pkg/devicemapper/devmapper.go | 13 ---- pkg/devicemapper/devmapper_log.go | 92 ++++++++++++++++++++++- 3 files changed, 96 insertions(+), 50 deletions(-) diff --git a/daemon/graphdriver/devmapper/deviceset.go b/daemon/graphdriver/devmapper/deviceset.go index c0116c7993..c785962ceb 100644 --- a/daemon/graphdriver/devmapper/deviceset.go +++ b/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 } diff --git a/pkg/devicemapper/devmapper.go b/pkg/devicemapper/devmapper.go index 8f35914366..ebd42bce2f 100644 --- a/pkg/devicemapper/devmapper.go +++ b/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 { diff --git a/pkg/devicemapper/devmapper_log.go b/pkg/devicemapper/devmapper_log.go index 7dd0c60891..098d2405ed 100644 --- a/pkg/devicemapper/devmapper_log.go +++ b/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() +} From 198f83bba120c6c9bda679d33a55acab6cc9f33d Mon Sep 17 00:00:00 2001 From: Aleksa Sarai Date: Wed, 28 Jun 2017 01:47:05 +1000 Subject: [PATCH 4/4] devicemapper: add --storage-opt dm.libdm_log_level=X option Because we use our own logging callbacks in order to use libdm effectively, it is quite difficult to debug complicated devicemapper issues (because any warnings or notices from libdm are muted by our own callback function). e07d3cd9a ("devmapper: Fix libdm logging") further reduced the ability of this debugging by only allowing _LOG_FATAL errors to be passed to the output. Unfortunately libdm is very chatty, so in order to avoid making the logs even more crowded, add a dm.libdm_log_level storage option that allows people who are debugging the lovely world of libdm to be able to dive in without recompiling binaries. The valid values of dm.libdm_log_level map directly to the libdm logging levels, and are in the range [2,7] as of the time of writing with 7 being _LOG_DEBUG and 2 being _LOG_FATAL. The default is _LOG_FATAL. Signed-off-by: Aleksa Sarai --- daemon/graphdriver/devmapper/deviceset.go | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/daemon/graphdriver/devmapper/deviceset.go b/daemon/graphdriver/devmapper/deviceset.go index c785962ceb..5c1856a79f 100644 --- a/daemon/graphdriver/devmapper/deviceset.go +++ b/daemon/graphdriver/devmapper/deviceset.go @@ -2761,6 +2761,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) }