Merge pull request #12033 from rhvgoyal/devmapper-cleanup

Devmapper Graph Driver Misc cleanup

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 <device_set_prefix>-<hash> 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 <device_set_prefix>-<hash> 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 {

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)