diff --git a/daemon/graphdriver/devmapper/deviceset.go b/daemon/graphdriver/devmapper/deviceset.go index 4d35adabc0..a5ad0e676c 100644 --- a/daemon/graphdriver/devmapper/deviceset.go +++ b/daemon/graphdriver/devmapper/deviceset.go @@ -33,6 +33,10 @@ var ( DefaultThinpBlockSize uint32 = 128 // 64K = 128 512b sectors MaxDeviceId int = 0xffffff // 24 bit, pool limit DeviceIdMapSz int = (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. + DMLogLevel int = devicemapper.LogLevelFatal ) const deviceSetMetaFile string = "deviceset-metadata" @@ -723,14 +727,22 @@ func setCloseOnExec(name string) { } func (devices *DeviceSet) DMLog(level int, file string, line int, dmError int, message string) { - if level >= devicemapper.LogLevelDebug { - // (vbatts) libdm debug is very verbose. If you're debugging libdm, you can - // comment out this check yourself - level = devicemapper.LogLevelInfo + // 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 > DMLogLevel { + return } // FIXME(vbatts) push this back into ./pkg/devicemapper/ - logrus.Debugf("libdevmapper(%d): %s:%d (%d) %s", level, file, line, dmError, message) + 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 { @@ -947,11 +959,6 @@ func (devices *DeviceSet) closeTransaction() error { } func (devices *DeviceSet) initDevmapper(doInit bool) error { - if os.Getenv("DEBUG") != "" { - devicemapper.LogInitVerbose(devicemapper.LogLevelDebug) - } else { - devicemapper.LogInitVerbose(devicemapper.LogLevelWarn) - } // give ourselves to libdm as a log handler devicemapper.LogInit(devices) @@ -1150,7 +1157,7 @@ func (devices *DeviceSet) deleteDevice(info *DevInfo) error { devinfo, _ := devicemapper.GetInfo(info.Name()) if devinfo != nil && devinfo.Exists != 0 { - if err := devices.removeDeviceAndWait(info.Name()); err != nil { + if err := devices.removeDevice(info.Name()); err != nil { logrus.Debugf("Error removing device: %s", err) return err } @@ -1218,18 +1225,12 @@ func (devices *DeviceSet) deactivateDevice(info *DevInfo) error { logrus.Debugf("[devmapper] deactivateDevice(%s)", info.Hash) defer logrus.Debugf("[devmapper] deactivateDevice END(%s)", info.Hash) - // Wait for the unmount to be effective, - // by watching the value of Info.OpenCount for the device - if err := devices.waitClose(info); err != nil { - logrus.Errorf("Error waiting for device %s to close: %s", info.Hash, err) - } - devinfo, err := devicemapper.GetInfo(info.Name()) if err != nil { return err } if devinfo.Exists != 0 { - if err := devices.removeDeviceAndWait(info.Name()); err != nil { + if err := devices.removeDevice(info.Name()); err != nil { return err } } @@ -1237,12 +1238,14 @@ func (devices *DeviceSet) deactivateDevice(info *DevInfo) error { return nil } -// Issues the underlying dm remove operation and then waits -// for it to finish. -func (devices *DeviceSet) removeDeviceAndWait(devname string) error { +// Issues the underlying dm remove operation. +func (devices *DeviceSet) removeDevice(devname string) error { var err error - for i := 0; i < 1000; i++ { + logrus.Debugf("[devmapper] removeDevice START(%s)", devname) + defer logrus.Debugf("[devmapper] removeDevice END(%s)", devname) + + for i := 0; i < 200; i++ { err = devicemapper.RemoveDevice(devname) if err == nil { break @@ -1254,74 +1257,11 @@ func (devices *DeviceSet) removeDeviceAndWait(devname string) error { // If we see EBUSY it may be a transient error, // sleep a bit a retry a few times. devices.Unlock() - time.Sleep(10 * time.Millisecond) + time.Sleep(100 * time.Millisecond) devices.Lock() } - if err != nil { - return err - } - if err := devices.waitRemove(devname); err != nil { - return err - } - return nil -} - -// waitRemove blocks until either: -// a) the device registered at - is removed, -// or b) the 10 second timeout expires. -func (devices *DeviceSet) waitRemove(devname string) error { - logrus.Debugf("[deviceset %s] waitRemove(%s)", devices.devicePrefix, devname) - defer logrus.Debugf("[deviceset %s] waitRemove(%s) END", devices.devicePrefix, devname) - i := 0 - for ; i < 1000; i++ { - devinfo, err := devicemapper.GetInfo(devname) - if err != nil { - // If there is an error we assume the device doesn't exist. - // The error might actually be something else, but we can't differentiate. - return nil - } - if i%100 == 0 { - logrus.Debugf("Waiting for removal of %s: exists=%d", devname, devinfo.Exists) - } - if devinfo.Exists == 0 { - break - } - - devices.Unlock() - time.Sleep(10 * time.Millisecond) - devices.Lock() - } - if i == 1000 { - return fmt.Errorf("Timeout while waiting for device %s to be removed", devname) - } - return nil -} - -// waitClose blocks until either: -// a) the device registered at - is closed, -// or b) the 10 second timeout expires. -func (devices *DeviceSet) waitClose(info *DevInfo) error { - i := 0 - for ; i < 1000; i++ { - devinfo, err := devicemapper.GetInfo(info.Name()) - if err != nil { - return err - } - if i%100 == 0 { - logrus.Debugf("Waiting for unmount of %s: opencount=%d", info.Hash, devinfo.OpenCount) - } - if devinfo.OpenCount == 0 { - break - } - devices.Unlock() - time.Sleep(10 * time.Millisecond) - devices.Lock() - } - if i == 1000 { - return fmt.Errorf("Timeout while waiting for device %s to close", info.Hash) - } - return nil + return err } func (devices *DeviceSet) Shutdown() error { diff --git a/pkg/devicemapper/devmapper.go b/pkg/devicemapper/devmapper.go index e8341692a4..bb89f7fac2 100644 --- a/pkg/devicemapper/devmapper.go +++ b/pkg/devicemapper/devmapper.go @@ -284,9 +284,9 @@ func FindLoopDeviceFor(file *os.File) *os.File { return nil } -func UdevWait(cookie uint) error { - if res := DmUdevWait(cookie); res != 1 { - logrus.Debugf("Failed to wait on udev cookie %d", cookie) +func UdevWait(cookie *uint) error { + if res := DmUdevWait(*cookie); res != 1 { + logrus.Debugf("Failed to wait on udev cookie %d", *cookie) return ErrUdevWait } return nil @@ -349,8 +349,6 @@ func CookieSupported() bool { // Useful helper for cleanup func RemoveDevice(name string) error { - logrus.Debugf("[devmapper] RemoveDevice START(%s)", name) - defer logrus.Debugf("[devmapper] RemoveDevice END(%s)", name) task, err := TaskCreateNamed(DeviceRemove, name) if task == nil { return err @@ -360,7 +358,7 @@ func RemoveDevice(name string) error { if err := task.SetCookie(&cookie, 0); err != nil { return fmt.Errorf("Can not set cookie: %s", err) } - defer UdevWait(cookie) + defer UdevWait(&cookie) dmSawBusy = false // reset before the task is run if err = task.Run(); err != nil { @@ -427,7 +425,7 @@ func CreatePool(poolName string, dataFile, metadataFile *os.File, poolBlockSize if err := task.SetCookie(&cookie, flags); err != nil { return fmt.Errorf("Can't set cookie %s", err) } - defer UdevWait(cookie) + defer UdevWait(&cookie) if err := task.Run(); err != nil { return fmt.Errorf("Error running DeviceCreate (CreatePool) %s", err) @@ -558,7 +556,7 @@ func ResumeDevice(name string) error { if err := task.SetCookie(&cookie, 0); err != nil { return fmt.Errorf("Can't set cookie %s", err) } - defer UdevWait(cookie) + defer UdevWait(&cookie) if err := task.Run(); err != nil { return fmt.Errorf("Error running DeviceResume %s", err) @@ -634,7 +632,7 @@ func ActivateDevice(poolName string, name string, deviceId int, size uint64) err return fmt.Errorf("Can't set cookie %s", err) } - defer UdevWait(cookie) + defer UdevWait(&cookie) if err := task.Run(); err != nil { return fmt.Errorf("Error running DeviceCreate (ActivateDevice) %s", err)