diff --git a/images/sds-local-volume-csi/driver/controller.go b/images/sds-local-volume-csi/driver/controller.go index 720156dc..5f4e3283 100644 --- a/images/sds-local-volume-csi/driver/controller.go +++ b/images/sds-local-volume-csi/driver/controller.go @@ -34,9 +34,9 @@ import ( func (d *Driver) CreateVolume(ctx context.Context, request *csi.CreateVolumeRequest) (*csi.CreateVolumeResponse, error) { d.log.Info("method CreateVolume") - d.log.Trace("========== CreateVolume ============") + d.log.Trace("[CreateVolume] ========== CreateVolume ============") d.log.Trace(request.String()) - d.log.Trace("========== CreateVolume ============") + d.log.Trace("[CreateVolume] ========== CreateVolume ============") if request.GetParameters()[internal.TypeKey] != internal.Lvm { return nil, status.Error(codes.InvalidArgument, "Unsupported Storage Class type") @@ -45,30 +45,31 @@ func (d *Driver) CreateVolume(ctx context.Context, request *csi.CreateVolumeRequ if len(request.Name) == 0 { return nil, status.Error(codes.InvalidArgument, "Volume Name cannot be empty") } + volumeName := request.Name if request.VolumeCapabilities == nil { return nil, status.Error(codes.InvalidArgument, "Volume Capability cannot de empty") } BindingMode := request.GetParameters()[internal.BindingModeKey] - d.log.Info(fmt.Sprintf("storage class BindingMode: %s", BindingMode)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] storage class BindingMode: %s", volumeName, BindingMode)) LvmType := request.GetParameters()[internal.LvmTypeKey] - d.log.Info(fmt.Sprintf("storage class LvmType: %s", LvmType)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] storage class LvmType: %s", volumeName, LvmType)) if len(request.GetParameters()[internal.LvmVolumeGroupKey]) == 0 { err := errors.New("no LVMVolumeGroups specified in a storage class's parameters") - d.log.Error(err, fmt.Sprintf("no LVMVolumeGroups were found for the request: %+v", request)) + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] no LVMVolumeGroups were found for the request: %+v", volumeName, request)) return nil, status.Errorf(codes.InvalidArgument, err.Error()) } storageClassLVGs, storageClassLVGParametersMap, err := utils.GetStorageClassLVGsAndParameters(ctx, d.cl, d.log, request.GetParameters()[internal.LvmVolumeGroupKey]) if err != nil { - d.log.Error(err, "error GetStorageClassLVGs") + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] error GetStorageClassLVGs", volumeName)) return nil, status.Errorf(codes.Internal, err.Error()) } contiguous := utils.IsContiguous(request, LvmType) - d.log.Info(fmt.Sprintf("contiguous: %t", contiguous)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] contiguous: %t", volumeName, contiguous)) // TODO: Consider refactoring the naming strategy for llvName and lvName. // Currently, we use the same name for llvName (the name of the LVMLogicalVolume resource in Kubernetes) @@ -76,76 +77,79 @@ func (d *Driver) CreateVolume(ctx context.Context, request *csi.CreateVolumeRequ // preventing name collisions. This approach simplifies matching between nodes and Kubernetes by maintaining // the same name in both contexts. Future consideration should be given to optimizing this logic to enhance // code readability and maintainability. - llvName := request.Name - lvName := request.Name - d.log.Info(fmt.Sprintf("llv name: %s ", llvName)) + llvName := volumeName + lvName := volumeName + d.log.Info(fmt.Sprintf("[CreateVolume][%s] llv name: %s", volumeName, llvName)) llvSize := resource.NewQuantity(request.CapacityRange.GetRequiredBytes(), resource.BinarySI) - d.log.Info(fmt.Sprintf("llv size: %s ", llvSize.String())) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] llv size: %s", volumeName, llvSize.String())) var preferredNode string switch BindingMode { case internal.BindingModeI: - d.log.Info(fmt.Sprintf("BindingMode is %s. Start selecting node", internal.BindingModeI)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] BindingMode is %s. Start selecting node", volumeName, internal.BindingModeI)) selectedNodeName, freeSpace, err := utils.GetNodeWithMaxFreeSpace(storageClassLVGs, storageClassLVGParametersMap, LvmType) if err != nil { - d.log.Error(err, "error GetNodeMaxVGSize") + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] error GetNodeMaxVGSize", volumeName)) } preferredNode = selectedNodeName - d.log.Info(fmt.Sprintf("Selected node: %s, free space %s ", selectedNodeName, freeSpace.String())) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] Selected node: %s, free space %s", volumeName, selectedNodeName, freeSpace.String())) if LvmType == internal.LVMTypeThick { if llvSize.Value() > freeSpace.Value() { return nil, status.Errorf(codes.Internal, "requested size: %s is greater than free space: %s", llvSize.String(), freeSpace.String()) } } case internal.BindingModeWFFC: - d.log.Info(fmt.Sprintf("BindingMode is %s. Get preferredNode", internal.BindingModeWFFC)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] BindingMode is %s. Get preferredNode", volumeName, internal.BindingModeWFFC)) if len(request.AccessibilityRequirements.Preferred) != 0 { t := request.AccessibilityRequirements.Preferred[0].Segments preferredNode = t[internal.TopologyKey] } } + d.log.Trace(fmt.Sprintf("[CreateVolume][%s] preferredNode: %s. Select LVG", volumeName, preferredNode)) selectedLVG, err := utils.SelectLVG(storageClassLVGs, preferredNode) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] selectedLVG: %+v", volumeName, selectedLVG)) if err != nil { - d.log.Error(err, "error SelectLVG") + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] error SelectLVG", volumeName)) return nil, status.Errorf(codes.Internal, err.Error()) } llvSpec := utils.GetLLVSpec(d.log, lvName, selectedLVG, storageClassLVGParametersMap, LvmType, *llvSize, contiguous) - d.log.Info(fmt.Sprintf("LVMLogicalVolumeSpec : %+v", llvSpec)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] LVMLogicalVolumeSpec: %+v", volumeName, llvSpec)) resizeDelta, err := resource.ParseQuantity(internal.ResizeDelta) if err != nil { - d.log.Error(err, "error ParseQuantity for ResizeDelta") + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] error ParseQuantity for ResizeDelta", volumeName)) return nil, err } - d.log.Trace("------------ CreateLVMLogicalVolume start ------------") - _, err = utils.CreateLVMLogicalVolume(ctx, d.cl, llvName, llvSpec) + d.log.Trace(fmt.Sprintf("[CreateVolume][%s] ------------ CreateLVMLogicalVolume start ------------", volumeName)) + _, err = utils.CreateLVMLogicalVolume(ctx, d.cl, d.log, llvName, llvSpec) if err != nil { if kerrors.IsAlreadyExists(err) { - d.log.Info(fmt.Sprintf("LVMLogicalVolume %s already exists", llvName)) + d.log.Info(fmt.Sprintf("[CreateVolume][%s] LVMLogicalVolume %s already exists. Skip creating", volumeName, llvName)) } else { - d.log.Error(err, "error CreateLVMLogicalVolume") + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] error CreateLVMLogicalVolume", volumeName)) return nil, err } } - d.log.Trace("------------ CreateLVMLogicalVolume end ------------") + d.log.Trace(fmt.Sprintf("[CreateVolume][%s] ------------ CreateLVMLogicalVolume end ------------", volumeName)) - d.log.Trace("start wait CreateLVMLogicalVolume ") + d.log.Trace(fmt.Sprintf("[CreateVolume][%s] start wait CreateLVMLogicalVolume", volumeName)) attemptCounter, err := utils.WaitForStatusUpdate(ctx, d.cl, d.log, request.Name, "", *llvSize, resizeDelta) if err != nil { - deleteErr := utils.DeleteLVMLogicalVolume(ctx, d.cl, d.log, request.Name) + d.log.Error(err, fmt.Sprintf("[CreateVolume][%s] error WaitForStatusUpdate. Delete LVMLogicalVolume %s", volumeName, request.Name)) - d.log.Error(err, fmt.Sprintf("error WaitForStatusUpdate. Delete LVMLogicalVolume %s", request.Name)) + deleteErr := utils.DeleteLVMLogicalVolume(ctx, d.cl, d.log, request.Name) if deleteErr != nil { - d.log.Error(deleteErr, "error DeleteLVMLogicalVolume") + d.log.Error(deleteErr, fmt.Sprintf("[CreateVolume][%s] error DeleteLVMLogicalVolume", volumeName)) } + return nil, err } - d.log.Trace(fmt.Sprintf("stop waiting CreateLVMLogicalVolume, attempt counter = %d ", attemptCounter)) + d.log.Trace(fmt.Sprintf("[CreateVolume][%s] finish wait CreateLVMLogicalVolume, attempt counter = %d", volumeName, attemptCounter)) volumeCtx := make(map[string]string, len(request.Parameters)) for k, v := range request.Parameters { @@ -160,6 +164,8 @@ func (d *Driver) CreateVolume(ctx context.Context, request *csi.CreateVolumeRequ volumeCtx[internal.ThinPoolNameKey] = "" } + d.log.Info(fmt.Sprintf("[CreateVolume][%s] Volume created successfully. volumeCtx: %+v", volumeName, volumeCtx)) + return &csi.CreateVolumeResponse{ Volume: &csi.Volume{ CapacityBytes: request.CapacityRange.GetRequiredBytes(), diff --git a/images/sds-local-volume-csi/pkg/utils/func.go b/images/sds-local-volume-csi/pkg/utils/func.go index e64bb397..14f5ea76 100644 --- a/images/sds-local-volume-csi/pkg/utils/func.go +++ b/images/sds-local-volume-csi/pkg/utils/func.go @@ -45,7 +45,7 @@ const ( SDSLocalVolumeCSIFinalizer = "storage.deckhouse.io/sds-local-volume-csi" ) -func CreateLVMLogicalVolume(ctx context.Context, kc client.Client, name string, lvmLogicalVolumeSpec snc.LVMLogicalVolumeSpec) (*snc.LVMLogicalVolume, error) { +func CreateLVMLogicalVolume(ctx context.Context, kc client.Client, log *logger.Logger, name string, lvmLogicalVolumeSpec snc.LVMLogicalVolumeSpec) (*snc.LVMLogicalVolume, error) { var err error llv := &snc.LVMLogicalVolume{ ObjectMeta: metav1.ObjectMeta{ @@ -56,7 +56,9 @@ func CreateLVMLogicalVolume(ctx context.Context, kc client.Client, name string, Spec: lvmLogicalVolumeSpec, } + log.Trace(fmt.Sprintf("[CreateLVMLogicalVolume][%s] LVMLogicalVolume: %+v", name, llv)) for attempt := 0; attempt < KubernetesAPIRequestLimit; attempt++ { + log.Trace(fmt.Sprintf("[CreateLVMLogicalVolume][%s] Attempt: %d", name, attempt)) err = kc.Create(ctx, llv) if err == nil { return llv, nil @@ -66,7 +68,8 @@ func CreateLVMLogicalVolume(ctx context.Context, kc client.Client, name string, return nil, err } - time.Sleep(KubernetesAPIRequestTimeout) + log.Warning(fmt.Sprintf("[CreateLVMLogicalVolume][%s] error: %s. Retry after %d seconds", name, err.Error(), KubernetesAPIRequestTimeout)) + time.Sleep(KubernetesAPIRequestTimeout * time.Second) } if err != nil { @@ -114,8 +117,10 @@ func WaitForStatusUpdate(ctx context.Context, kc client.Client, log *logger.Logg attemptCounter++ select { case <-ctx.Done(): + log.Warning(fmt.Sprintf("[WaitForStatusUpdate][%s] context done. Failed to wait for LVM Logical Volume status update", lvmLogicalVolumeName)) return attemptCounter, ctx.Err() - case <-time.After(500 * time.Millisecond): + default: + time.Sleep(500 * time.Millisecond) } llv, err := GetLVMLogicalVolume(ctx, kc, lvmLogicalVolumeName, namespace) @@ -124,10 +129,11 @@ func WaitForStatusUpdate(ctx context.Context, kc client.Client, log *logger.Logg } if attemptCounter%10 == 0 { - log.Info(fmt.Sprintf("[WaitForStatusUpdate] Attempt: %d,LVM Logical Volume: %+v; delta=%s; sizeEquals=%t", attemptCounter, llv, delta.String(), sizeEquals)) + log.Info(fmt.Sprintf("[WaitForStatusUpdate][%s] Attempt: %d,LVM Logical Volume: %+v; delta=%s; sizeEquals=%t", lvmLogicalVolumeName, attemptCounter, llv, delta.String(), sizeEquals)) } if llv.Status != nil { + log.Trace(fmt.Sprintf("[WaitForStatusUpdate][%s] LVM Logical Volume status: %+v", lvmLogicalVolumeName, llv.Status)) sizeEquals = AreSizesEqualWithinDelta(llvSize, llv.Status.ActualSize, delta) if llv.Status.Phase == LLVStatusFailed { @@ -137,6 +143,7 @@ func WaitForStatusUpdate(ctx context.Context, kc client.Client, log *logger.Logg if llv.Status.Phase == LLVStatusCreated && sizeEquals { return attemptCounter, nil } + log.Trace(fmt.Sprintf("[WaitForStatusUpdate][%s] LVM Logical Volume status does not have the required fields yet. Waiting...", lvmLogicalVolumeName)) } } }