diff --git a/images/virtualization-artifact/pkg/controller/vd/internal/source/object_ref_vi.go b/images/virtualization-artifact/pkg/controller/vd/internal/source/object_ref_vi.go index ecf5891a25..bade3e7061 100644 --- a/images/virtualization-artifact/pkg/controller/vd/internal/source/object_ref_vi.go +++ b/images/virtualization-artifact/pkg/controller/vd/internal/source/object_ref_vi.go @@ -20,7 +20,9 @@ import ( "context" "errors" "fmt" + "reflect" + "github.com/deckhouse/virtualization-controller/pkg/logger" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/types" cdiv1 "kubevirt.io/containerized-data-importer-api/pkg/apis/core/v1beta1" @@ -71,6 +73,8 @@ func (ds ObjectRefVirtualImage) Sync(ctx context.Context, vd *v1alpha2.VirtualDi return reconcile.Result{}, fmt.Errorf("fetch dv: %w", err) } + logger.FromContext(ctx).Info("[GOGOGO] Reconcile virtual disk", "datavolume", safenil(dv), "pvc", safenil(pvc)) + return steptaker.NewStepTakers[*v1alpha2.VirtualDisk]( step.NewReadyStep(ds.diskService, pvc, cb), step.NewTerminatingStep(pvc), @@ -81,6 +85,14 @@ func (ds ObjectRefVirtualImage) Sync(ctx context.Context, vd *v1alpha2.VirtualDi ).Run(ctx, vd) } +func safenil(o client.Object) string { + if o == nil || reflect.ValueOf(o).IsNil() { + return "nil" + } + + return o.GetName() +} + func (ds ObjectRefVirtualImage) Validate(ctx context.Context, vd *v1alpha2.VirtualDisk) error { if vd.Spec.DataSource == nil || vd.Spec.DataSource.ObjectRef == nil { return errors.New("object ref missed for data source") diff --git a/images/virtualization-artifact/pkg/controller/vd/internal/source/step/create_dv_from_vi_step.go b/images/virtualization-artifact/pkg/controller/vd/internal/source/step/create_dv_from_vi_step.go index 959f65ecfd..135ab9ddbe 100644 --- a/images/virtualization-artifact/pkg/controller/vd/internal/source/step/create_dv_from_vi_step.go +++ b/images/virtualization-artifact/pkg/controller/vd/internal/source/step/create_dv_from_vi_step.go @@ -21,6 +21,7 @@ import ( "errors" "fmt" + "github.com/deckhouse/virtualization-controller/pkg/logger" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/resource" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -69,6 +70,8 @@ func (s CreateDataVolumeFromVirtualImageStep) Take(ctx context.Context, vd *v1al return nil, nil } + logger.FromContext(ctx).Info("[GOGOGO] STEP CreateDataVolumeFromVirtualImageStep") + viRefKey := types.NamespacedName{Name: vd.Spec.DataSource.ObjectRef.Name, Namespace: vd.Namespace} viRef, err := object.FetchObject(ctx, viRefKey, s.client, &v1alpha2.VirtualImage{}) if err != nil { diff --git a/images/virtualization-artifact/pkg/controller/vd/internal/source/step/wait_for_dv_step.go b/images/virtualization-artifact/pkg/controller/vd/internal/source/step/wait_for_dv_step.go index 667be675e0..4c3ec7afe3 100644 --- a/images/virtualization-artifact/pkg/controller/vd/internal/source/step/wait_for_dv_step.go +++ b/images/virtualization-artifact/pkg/controller/vd/internal/source/step/wait_for_dv_step.go @@ -19,8 +19,10 @@ package step import ( "context" "fmt" + "reflect" "strings" + "github.com/deckhouse/virtualization-controller/pkg/logger" corev1 "k8s.io/api/core/v1" storagev1 "k8s.io/api/storage/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -66,13 +68,25 @@ func NewWaitForDVStep( } } +func safenil(o client.Object) string { + if o == nil || reflect.ValueOf(o).IsNil() { + return "nil" + } + + return o.GetName() +} + func (s WaitForDVStep) Take(ctx context.Context, vd *v1alpha2.VirtualDisk) (*reconcile.Result, error) { + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep", "datavolume", safenil(s.dv), "sc", vd.Status.StorageClassName) + if s.dv == nil { vd.Status.Phase = v1alpha2.DiskProvisioning s.cb. Status(metav1.ConditionFalse). Reason(vdcondition.Provisioning). Message("Waiting for the VirtualDisk importer to be created.") + + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep [importer to be created]") return &reconcile.Result{}, nil } @@ -88,11 +102,13 @@ func (s WaitForDVStep) Take(ctx context.Context, vd *v1alpha2.VirtualDisk) (*rec return &reconcile.Result{}, nil } if set { + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep [consumer awaited]") return &reconcile.Result{}, nil } ok = s.checkRunningCondition(vd) if !ok { + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep [checkRunningCondition]") return &reconcile.Result{}, nil } @@ -106,9 +122,12 @@ func (s WaitForDVStep) Take(ctx context.Context, vd *v1alpha2.VirtualDisk) (*rec set = s.setForProvisioning(vd) if set { + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep [provisioning to the pvc]") return &reconcile.Result{}, nil } + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep [ok]") + return nil, nil } @@ -126,6 +145,8 @@ func (s WaitForDVStep) setForProvisioning(vd *v1alpha2.VirtualDisk) (set bool) { } func (s WaitForDVStep) setForFirstConsumerIsAwaited(ctx context.Context, vd *v1alpha2.VirtualDisk) (set bool, err error) { + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep setForFirstConsumerIsAwaited 111") + if vd.Status.StorageClassName == "" { return false, fmt.Errorf("StorageClassName is empty, please report a bug") } @@ -138,6 +159,9 @@ func (s WaitForDVStep) setForFirstConsumerIsAwaited(ctx context.Context, vd *v1a isWFFC := sc != nil && sc.VolumeBindingMode != nil && *sc.VolumeBindingMode == storagev1.VolumeBindingWaitForFirstConsumer dvRunningCond, _ := conditions.GetDataVolumeCondition(conditions.DVRunningConditionType, s.dv.Status.Conditions) dvRunningReasonEmptyOrPending := dvRunningCond.Reason == "" || dvRunningCond.Reason == conditions.DVRunningConditionPendingReason + + logger.FromContext(ctx).Info("[GOGOGO] STEP WaitForDVStep setForFirstConsumerIsAwaited 222", "isWFFC", isWFFC, "dvPhase", s.dv.Status.Phase, "dvRunningReasonEmptyOrPending", dvRunningReasonEmptyOrPending) + if isWFFC && (s.dv.Status.Phase == cdiv1.PendingPopulation || s.dv.Status.Phase == cdiv1.WaitForFirstConsumer) && dvRunningReasonEmptyOrPending { vd.Status.Phase = v1alpha2.DiskWaitForFirstConsumer s.cb. diff --git a/images/virtualization-artifact/pkg/controller/vd/internal/watcher/datavolume_watcher.go b/images/virtualization-artifact/pkg/controller/vd/internal/watcher/datavolume_watcher.go index c03cbfd6f2..d6e805d4ce 100644 --- a/images/virtualization-artifact/pkg/controller/vd/internal/watcher/datavolume_watcher.go +++ b/images/virtualization-artifact/pkg/controller/vd/internal/watcher/datavolume_watcher.go @@ -18,7 +18,9 @@ package watcher import ( "fmt" + "strings" + "github.com/deckhouse/deckhouse/pkg/log" cdiv1 "kubevirt.io/containerized-data-importer-api/pkg/apis/core/v1beta1" "sigs.k8s.io/controller-runtime/pkg/controller" "sigs.k8s.io/controller-runtime/pkg/event" @@ -31,10 +33,14 @@ import ( "github.com/deckhouse/virtualization/api/core/v1alpha2" ) -type DataVolumeWatcher struct{} +type DataVolumeWatcher struct { + logger *log.Logger +} func NewDataVolumeWatcher() *DataVolumeWatcher { - return &DataVolumeWatcher{} + return &DataVolumeWatcher{ + logger: log.Default().With("watcher", strings.ToLower("DataVolume")), + } } func (w *DataVolumeWatcher) Watch(mgr manager.Manager, ctr controller.Controller) error { @@ -49,15 +55,20 @@ func (w *DataVolumeWatcher) Watch(mgr manager.Manager, ctr controller.Controller predicate.TypedFuncs[*cdiv1.DataVolume]{ CreateFunc: func(e event.TypedCreateEvent[*cdiv1.DataVolume]) bool { return false }, UpdateFunc: func(e event.TypedUpdateEvent[*cdiv1.DataVolume]) bool { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed") + if e.ObjectOld.Status.Progress != e.ObjectNew.Status.Progress { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [e.ObjectOld.Status.Progress != e.ObjectNew.Status.Progress]") return true } if e.ObjectOld.Status.Phase != e.ObjectNew.Status.Phase && e.ObjectNew.Status.Phase == cdiv1.Succeeded { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [e.ObjectNew.Status.Phase == cdiv1.Succeeded]") return true } if e.ObjectOld.Status.ClaimName != e.ObjectNew.Status.ClaimName { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [e.ObjectOld.Status.ClaimName != e.ObjectNew.Status.ClaimName]") return true } @@ -65,10 +76,12 @@ func (w *DataVolumeWatcher) Watch(mgr manager.Manager, ctr controller.Controller newDVQuotaNotExceeded, newOk := conditions.GetDataVolumeCondition(conditions.DVQoutaNotExceededConditionType, e.ObjectNew.Status.Conditions) if !oldOk && newOk { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [quota]") return true } if oldOk && newOk && oldDVQuotaNotExceeded != newDVQuotaNotExceeded { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [quota 2]") return true } @@ -76,10 +89,19 @@ func (w *DataVolumeWatcher) Watch(mgr manager.Manager, ctr controller.Controller newDVRunning, _ := conditions.GetDataVolumeCondition(conditions.DVRunningConditionType, e.ObjectNew.Status.Conditions) if oldDVRunning.Reason != newDVRunning.Reason { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [oldDVRunning.Reason != newDVRunning.Reason]") return true } - return newDVRunning.Reason == "Error" || newDVRunning.Reason == "ImagePullFailed" + f := newDVRunning.Reason == "Error" || newDVRunning.Reason == "ImagePullFailed" + if f { + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [oldDVRunning.Reason != newDVRunning.Reason]") + return true + } + + w.logger.Info("[GOGOGO] [DataVolumeWatcher] Event observed [FALSE]") + + return false }, }, ),