diff --git a/pkg/controller/volume/attachdetach/reconciler/reconciler.go b/pkg/controller/volume/attachdetach/reconciler/reconciler.go index 5af44bfa647..9cbbfe586d6 100644 --- a/pkg/controller/volume/attachdetach/reconciler/reconciler.go +++ b/pkg/controller/volume/attachdetach/reconciler/reconciler.go @@ -20,6 +20,7 @@ limitations under the License. package reconciler import ( + "fmt" "time" "github.com/golang/glog" @@ -142,9 +143,7 @@ func (rc *reconciler) reconcile() { timeout := elapsedTime > rc.maxWaitForUnmountDuration // Check whether volume is still mounted. Skip detach if it is still mounted unless timeout if attachedVolume.MountedByNode && !timeout { - glog.V(12).Infof("Cannot trigger detach for volume %q on node %q because volume is still mounted", - attachedVolume.VolumeName, - attachedVolume.NodeName) + glog.V(12).Infof(attachedVolume.GenerateMsgDetailed("Cannot detach volume because it is still mounted", "")) continue } @@ -162,26 +161,20 @@ func (rc *reconciler) reconcile() { err = rc.nodeStatusUpdater.UpdateNodeStatuses() if err != nil { // Skip detaching this volume if unable to update node status - glog.Errorf("UpdateNodeStatuses failed while attempting to report volume %q as attached to node %q with: %v ", - attachedVolume.VolumeName, - attachedVolume.NodeName, - err) + glog.Errorf(attachedVolume.GenerateErrorDetailed("UpdateNodeStatuses failed while attempting to report volume as attached", err).Error()) continue } // Trigger detach volume which requires verifing safe to detach step // If timeout is true, skip verifySafeToDetach check - glog.V(5).Infof("Attempting to start DetachVolume for volume %q from node %q", attachedVolume.VolumeName, attachedVolume.NodeName) + glog.V(5).Infof(attachedVolume.GenerateMsgDetailed("Starting attacherDetacher.DetachVolume", "")) verifySafeToDetach := !timeout err = rc.attacherDetacher.DetachVolume(attachedVolume.AttachedVolume, verifySafeToDetach, rc.actualStateOfWorld) if err == nil { if !timeout { - glog.Infof("Started DetachVolume for volume %q from node %q", attachedVolume.VolumeName, attachedVolume.NodeName) + glog.Infof(attachedVolume.GenerateMsgDetailed("attacherDetacher.DetachVolume started", "")) } else { - glog.Infof("Started DetachVolume for volume %q from node %q. This volume is not safe to detach, but maxWaitForUnmountDuration %v expired, force detaching", - attachedVolume.VolumeName, - attachedVolume.NodeName, - rc.maxWaitForUnmountDuration) + glog.Infof(attachedVolume.GenerateMsgDetailed("attacherDetacher.DetachVolume started", fmt.Sprintf("This volume is not safe to detach, but maxWaitForUnmountDuration %v expired, force detaching", rc.maxWaitForUnmountDuration))) } } if err != nil && @@ -189,11 +182,7 @@ func (rc *reconciler) reconcile() { !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists && exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.DetachVolume failed to start for volume %q from node %q with err: %v", - attachedVolume.VolumeName, - attachedVolume.NodeName, - err) + glog.Errorf(attachedVolume.GenerateErrorDetailed("attacherDetacher.DetachVolume failed to start", err).Error()) } } } @@ -203,26 +192,21 @@ func (rc *reconciler) reconcile() { if rc.actualStateOfWorld.VolumeNodeExists( volumeToAttach.VolumeName, volumeToAttach.NodeName) { // Volume/Node exists, touch it to reset detachRequestedTime - glog.V(5).Infof("Volume %q/Node %q is attached--touching.", volumeToAttach.VolumeName, volumeToAttach.NodeName) + glog.V(5).Infof(volumeToAttach.GenerateMsgDetailed("Volume attached--touching", "")) rc.actualStateOfWorld.ResetDetachRequestTime(volumeToAttach.VolumeName, volumeToAttach.NodeName) } else { // Volume/Node doesn't exist, spawn a goroutine to attach it - glog.V(5).Infof("Attempting to start AttachVolume for volume %q to node %q", volumeToAttach.VolumeName, volumeToAttach.NodeName) + glog.V(5).Infof(volumeToAttach.GenerateMsgDetailed("Starting attacherDetacher.AttachVolume", "")) err := rc.attacherDetacher.AttachVolume(volumeToAttach.VolumeToAttach, rc.actualStateOfWorld) if err == nil { - glog.Infof("Started AttachVolume for volume %q to node %q", volumeToAttach.VolumeName, volumeToAttach.NodeName) + glog.Infof(volumeToAttach.GenerateMsgDetailed("attacherDetacher.AttachVolume started", "")) } if err != nil && !nestedpendingoperations.IsAlreadyExists(err) && !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists && exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.AttachVolume failed to start for volume %q (spec.Name: %q) to node %q with err: %v", - volumeToAttach.VolumeName, - volumeToAttach.VolumeSpec.Name(), - volumeToAttach.NodeName, - err) + glog.Errorf(volumeToAttach.GenerateErrorDetailed("attacherDetacher.AttachVolume failed to start", err).Error()) } } } diff --git a/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go b/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go index d0dd565fb5f..144863623ea 100644 --- a/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go +++ b/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go @@ -240,11 +240,7 @@ func (dswp *desiredStateOfWorldPopulator) findAndRemoveDeletedPods() { continue } - glog.V(5).Infof( - "Removing volume %q (volSpec=%q) for pod %q from desired state.", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - format.Pod(volumeToMount.Pod)) + glog.V(5).Infof(volumeToMount.GenerateMsgDetailed("Removing volume from desired state", "")) dswp.desiredStateOfWorld.DeletePodFromVolume( volumeToMount.PodName, volumeToMount.VolumeName) diff --git a/pkg/kubelet/volumemanager/reconciler/reconciler.go b/pkg/kubelet/volumemanager/reconciler/reconciler.go index 32ce3261959..0bbee6ef263 100644 --- a/pkg/kubelet/volumemanager/reconciler/reconciler.go +++ b/pkg/kubelet/volumemanager/reconciler/reconciler.go @@ -172,11 +172,7 @@ func (rc *reconciler) reconcile() { for _, mountedVolume := range rc.actualStateOfWorld.GetMountedVolumes() { if !rc.desiredStateOfWorld.PodExistsInVolume(mountedVolume.PodName, mountedVolume.VolumeName) { // Volume is mounted, unmount it - glog.V(12).Infof("Attempting to start UnmountVolume for volume %q (spec.Name: %q) from pod %q (UID: %q).", - mountedVolume.VolumeName, - mountedVolume.OuterVolumeSpecName, - mountedVolume.PodName, - mountedVolume.PodUID) + glog.V(12).Infof(mountedVolume.GenerateMsgDetailed("Starting operationExecutor.UnmountVolume", "")) err := rc.operationExecutor.UnmountVolume( mountedVolume.MountedVolume, rc.actualStateOfWorld) if err != nil && @@ -184,21 +180,10 @@ func (rc *reconciler) reconcile() { !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists and exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.UnmountVolume failed for volume %q (spec.Name: %q) pod %q (UID: %q) controllerAttachDetachEnabled: %v with err: %v", - mountedVolume.VolumeName, - mountedVolume.OuterVolumeSpecName, - mountedVolume.PodName, - mountedVolume.PodUID, - rc.controllerAttachDetachEnabled, - err) + glog.Errorf(mountedVolume.GenerateErrorDetailed(fmt.Sprintf("operationExecutor.UnmountVolume failed (controllerAttachDetachEnabled %v)", rc.controllerAttachDetachEnabled), err).Error()) } if err == nil { - glog.Infof("UnmountVolume operation started for volume %q (spec.Name: %q) from pod %q (UID: %q).", - mountedVolume.VolumeName, - mountedVolume.OuterVolumeSpecName, - mountedVolume.PodName, - mountedVolume.PodUID) + glog.Infof(mountedVolume.GenerateMsgDetailed("operationExecutor.UnmountVolume started", "")) } } } @@ -211,11 +196,7 @@ func (rc *reconciler) reconcile() { if rc.controllerAttachDetachEnabled || !volumeToMount.PluginIsAttachable { // Volume is not attached (or doesn't implement attacher), kubelet attach is disabled, wait // for controller to finish attaching volume. - glog.V(12).Infof("Attempting to start VerifyControllerAttachedVolume for volume %q (spec.Name: %q) pod %q (UID: %q)", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID) + glog.V(12).Infof(volumeToMount.GenerateMsgDetailed("Starting operationExecutor.VerifyControllerAttachedVolume", "")) err := rc.operationExecutor.VerifyControllerAttachedVolume( volumeToMount.VolumeToMount, rc.nodeName, @@ -225,21 +206,10 @@ func (rc *reconciler) reconcile() { !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists and exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.VerifyControllerAttachedVolume failed for volume %q (spec.Name: %q) pod %q (UID: %q) controllerAttachDetachEnabled: %v with err: %v", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID, - rc.controllerAttachDetachEnabled, - err) + glog.Errorf(volumeToMount.GenerateErrorDetailed(fmt.Sprintf("operationExecutor.VerifyControllerAttachedVolume failed (controllerAttachDetachEnabled %v)", rc.controllerAttachDetachEnabled), err).Error()) } if err == nil { - glog.Infof("VerifyControllerAttachedVolume operation started for volume %q (spec.Name: %q) pod %q (UID: %q)", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID) + glog.Infof(volumeToMount.GenerateMsgDetailed("operationExecutor.VerifyControllerAttachedVolume started", "")) } } else { // Volume is not attached to node, kubelet attach is enabled, volume implements an attacher, @@ -249,32 +219,17 @@ func (rc *reconciler) reconcile() { VolumeSpec: volumeToMount.VolumeSpec, NodeName: rc.nodeName, } - glog.V(12).Infof("Attempting to start AttachVolume for volume %q (spec.Name: %q) pod %q (UID: %q)", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID) + glog.V(12).Infof(volumeToAttach.GenerateMsgDetailed("Starting operationExecutor.AttachVolume", "")) err := rc.operationExecutor.AttachVolume(volumeToAttach, rc.actualStateOfWorld) if err != nil && !nestedpendingoperations.IsAlreadyExists(err) && !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists and exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.AttachVolume failed for volume %q (spec.Name: %q) pod %q (UID: %q) controllerAttachDetachEnabled: %v with err: %v", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID, - rc.controllerAttachDetachEnabled, - err) + glog.Errorf(volumeToMount.GenerateErrorDetailed(fmt.Sprintf("operationExecutor.AttachVolume failed (controllerAttachDetachEnabled %v)", rc.controllerAttachDetachEnabled), err).Error()) } if err == nil { - glog.Infof("AttachVolume operation started for volume %q (spec.Name: %q) pod %q (UID: %q)", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID) + glog.Infof(volumeToMount.GenerateMsgDetailed("operationExecutor.AttachVolume started", "")) } } } else if !volMounted || cache.IsRemountRequiredError(err) { @@ -283,12 +238,7 @@ func (rc *reconciler) reconcile() { if cache.IsRemountRequiredError(err) { remountingLogStr = "Volume is already mounted to pod, but remount was requested." } - glog.V(12).Infof("Attempting to start MountVolume for volume %q (spec.Name: %q) to pod %q (UID: %q). %s", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID, - remountingLogStr) + glog.V(12).Infof(volumeToMount.GenerateMsgDetailed("Starting operationExecutor.MountVolume", remountingLogStr)) err := rc.operationExecutor.MountVolume( rc.waitForAttachTimeout, volumeToMount.VolumeToMount, @@ -298,26 +248,13 @@ func (rc *reconciler) reconcile() { !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists and exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.MountVolume failed for volume %q (spec.Name: %q) pod %q (UID: %q) controllerAttachDetachEnabled: %v with err: %v", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID, - rc.controllerAttachDetachEnabled, - err) + glog.Errorf(volumeToMount.GenerateErrorDetailed(fmt.Sprintf("operationExecutor.MountVolume failed (controllerAttachDetachEnabled %v)", rc.controllerAttachDetachEnabled), err).Error()) } if err == nil { - logMsg := fmt.Sprintf("MountVolume operation started for volume %q (spec.Name: %q) to pod %q (UID: %q). %s", - volumeToMount.VolumeName, - volumeToMount.VolumeSpec.Name(), - volumeToMount.PodName, - volumeToMount.Pod.UID, - remountingLogStr) if remountingLogStr == "" { - glog.V(1).Infof(logMsg) + glog.V(1).Infof(volumeToMount.GenerateMsgDetailed("operationExecutor.MountVolume started", remountingLogStr)) } else { - glog.V(5).Infof(logMsg) + glog.V(5).Infof(volumeToMount.GenerateMsgDetailed("operationExecutor.MountVolume started", remountingLogStr)) } } } @@ -330,9 +267,7 @@ func (rc *reconciler) reconcile() { !rc.operationExecutor.IsOperationPending(attachedVolume.VolumeName, nestedpendingoperations.EmptyUniquePodName) { if attachedVolume.GloballyMounted { // Volume is globally mounted to device, unmount it - glog.V(12).Infof("Attempting to start UnmountDevice for volume %q (spec.Name: %q)", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name()) + glog.V(12).Infof(attachedVolume.GenerateMsgDetailed("Starting operationExecutor.UnmountDevice", "")) err := rc.operationExecutor.UnmountDevice( attachedVolume.AttachedVolume, rc.actualStateOfWorld, rc.mounter) if err != nil && @@ -340,32 +275,20 @@ func (rc *reconciler) reconcile() { !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists and exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.UnmountDevice failed for volume %q (spec.Name: %q) controllerAttachDetachEnabled: %v with err: %v", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name(), - rc.controllerAttachDetachEnabled, - err) + glog.Errorf(attachedVolume.GenerateErrorDetailed(fmt.Sprintf("operationExecutor.UnmountDevice failed (controllerAttachDetachEnabled %v)", rc.controllerAttachDetachEnabled), err).Error()) } if err == nil { - glog.Infof("UnmountDevice operation started for volume %q (spec.Name: %q)", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name()) + glog.Infof(attachedVolume.GenerateMsgDetailed("operationExecutor.UnmountDevice started", "")) } } else { // Volume is attached to node, detach it // Kubelet not responsible for detaching or this volume has a non-attachable volume plugin. if rc.controllerAttachDetachEnabled || !attachedVolume.PluginIsAttachable { rc.actualStateOfWorld.MarkVolumeAsDetached(attachedVolume.VolumeName, attachedVolume.NodeName) - glog.Infof("Detached volume %q (spec.Name: %q) devicePath: %q", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name(), - attachedVolume.DevicePath) + glog.Infof(attachedVolume.GenerateMsgDetailed("Volume detached", fmt.Sprintf("DevicePath %q", attachedVolume.DevicePath))) } else { // Only detach if kubelet detach is enabled - glog.V(12).Infof("Attempting to start DetachVolume for volume %q (spec.Name: %q)", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name()) + glog.V(12).Infof(attachedVolume.GenerateMsgDetailed("Starting operationExecutor.DetachVolume", "")) err := rc.operationExecutor.DetachVolume( attachedVolume.AttachedVolume, false /* verifySafeToDetach */, rc.actualStateOfWorld) if err != nil && @@ -373,17 +296,10 @@ func (rc *reconciler) reconcile() { !exponentialbackoff.IsExponentialBackoff(err) { // Ignore nestedpendingoperations.IsAlreadyExists && exponentialbackoff.IsExponentialBackoff errors, they are expected. // Log all other errors. - glog.Errorf( - "operationExecutor.DetachVolume failed for volume %q (spec.Name: %q) controllerAttachDetachEnabled: %v with err: %v", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name(), - rc.controllerAttachDetachEnabled, - err) + glog.Errorf(attachedVolume.GenerateErrorDetailed(fmt.Sprintf("operationExecutor.DetachVolume failed (controllerAttachDetachEnabled %v)", rc.controllerAttachDetachEnabled), err).Error()) } if err == nil { - glog.Infof("DetachVolume operation started for volume %q (spec.Name: %q)", - attachedVolume.VolumeName, - attachedVolume.VolumeSpec.Name()) + glog.Infof(attachedVolume.GenerateMsgDetailed("operationExecutor.DetachVolume started", "")) } } }