Skip to content

Commit

Permalink
add some logs
Browse files Browse the repository at this point in the history 
Signed-off-by: Aleksandr Zimin <alexandr.zimin@flant.com>
  • Loading branch information
@AleksZimin
AleksZimin committed Aug 16, 2024
1 parent 821106f commit bf80d13
Show file tree
Hide file tree
Showing 2 changed files with 45 additions and 32 deletions.
62 changes: 34 additions & 28 deletions images/sds-local-volume-csi/driver/controller.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand All @@ -45,107 +45,111 @@ 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)
// and lvName (the name of the LV in LVM on the node) because the PV name is unique within the cluster,
// 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 {
Expand All @@ -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(),
Expand Down
15 changes: 11 additions & 4 deletions images/sds-local-volume-csi/pkg/utils/func.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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{
Expand All @@ -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
Expand All @@ -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 {
Expand Down Expand Up @@ -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)
Expand All @@ -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 {
Expand All @@ -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))
}
}
}
Expand Down

0 comments on commit bf80d13

Please sign in to comment.