Skip to content

Commit 2e26872

Browse files
valeryia-hurynovichvaleryia-hurynovich
authored
Merge pull request #10 from cobaltcore-dev/add-more-logs
Added more logs to debug reconciliation and gc flow
2 parents bb26ee8 + 98c8db6 commit 2e26872

3 files changed

Lines changed: 106 additions & 20 deletions

File tree

‎cloudprofilesync/imageupdater.go‎

Lines changed: 20 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -16,8 +16,9 @@ import (
1616

1717
func filterImages(log logr.Logger, versions []SourceImage) []SourceImage {
1818
filtered := make([]SourceImage, 0, len(versions))
19+
log.Info("starting to filter source images", "total_versions", len(versions))
1920
for _, version := range versions {
20-
_, err := semver.Parse(version.Version)
21+
parsed, err := semver.Parse(version.Version)
2122
if err != nil {
2223
log.V(1).Info("skipping invalid version", "version", version.Version)
2324
continue
@@ -26,8 +27,10 @@ func filterImages(log logr.Logger, versions []SourceImage) []SourceImage {
2627
log.V(1).Info("skipping version with no architectures", "version", version.Version)
2728
continue
2829
}
30+
log.V(1).Info("valid version found", "version", version.Version, "major", parsed.Major, "minor", parsed.Minor, "patch", parsed.Patch, "pre_release", parsed.Pre)
2931
filtered = append(filtered, version)
3032
}
33+
log.Info("finished filtering source images", "valid_versions", len(filtered))
3134
return filtered
3235
}
3336

@@ -42,32 +45,42 @@ func (iu *ImageUpdater) Update(ctx context.Context, cpSpec *gardenerv1beta1.Clou
4245
iu.Log.Info("checking source", "image", iu.ImageName)
4346
sourceImages, err := iu.Source.GetVersions(ctx)
4447
if err != nil {
45-
return fmt.Errorf("failed to retrieve images version from oci registry: %w", err)
48+
iu.Log.Error(err, "failed to retrieve image versions from OCI registry", "image", iu.ImageName, "error_msg", err.Error())
49+
return fmt.Errorf("failed to retrieve image versions from OCI registry: %w", err)
4650
}
47-
iu.Log.Info("checked source", "image", iu.ImageName)
51+
iu.Log.Info("retrieved source images", "count", len(sourceImages), "image", iu.ImageName)
4852
sourceImages = filterImages(iu.Log, sourceImages)
4953
// Images from a source arrive in no guaranteed order. A changed order
5054
// in the source images may lead to a changed order in the CloudProfile,
5155
// causing unnecesscary reconciliations.
56+
iu.Log.Info("filtered valid images", "count", len(sourceImages), "image", iu.ImageName)
57+
for _, img := range sourceImages {
58+
iu.Log.V(1).Info("valid source image", "version", img.Version, "architectures", img.Architectures)
59+
}
5260
slices.SortFunc(sourceImages, func(a, b SourceImage) int {
5361
return cmp.Compare(a.Version, b.Version)
5462
})
63+
iu.Log.V(1).Info("sorted source images", "image", iu.ImageName)
5564
imageIndex := slices.IndexFunc(cpSpec.MachineImages, func(img gardenerv1beta1.MachineImage) bool {
5665
return img.Name == iu.ImageName
5766
})
5867
if imageIndex == -1 {
5968
cpSpec.MachineImages = append(cpSpec.MachineImages, gardenerv1beta1.MachineImage{Name: iu.ImageName})
6069
imageIndex = len(cpSpec.MachineImages) - 1
70+
iu.Log.Info("created new MachineImage entry", "image", iu.ImageName)
6171
}
6272
image := &cpSpec.MachineImages[imageIndex]
6373
existingVersions := make(map[string]int, len(image.Versions))
6474
for idx, version := range image.Versions {
6575
existingVersions[version.Version] = idx
6676
}
77+
iu.Log.V(1).Info("existing versions in CloudProfile", "count", len(existingVersions), "image", iu.ImageName)
6778
for _, sourceImage := range sourceImages {
6879
if idx, exists := existingVersions[sourceImage.Version]; exists {
80+
iu.Log.V(1).Info("updating existing version architectures", "version", sourceImage.Version, "architectures", sourceImage.Architectures)
6981
image.Versions[idx].Architectures = sourceImage.Architectures
7082
} else {
83+
iu.Log.Info("adding new version to CloudProfile", "version", sourceImage.Version, "architectures", sourceImage.Architectures)
7184
image.Versions = append(image.Versions, gardenerv1beta1.MachineImageVersion{
7285
ExpirableVersion: gardenerv1beta1.ExpirableVersion{
7386
Version: sourceImage.Version,
@@ -77,9 +90,13 @@ func (iu *ImageUpdater) Update(ctx context.Context, cpSpec *gardenerv1beta1.Clou
7790
}
7891
}
7992
if iu.Provider != nil {
93+
iu.Log.Info("invoking provider Configure", "image", iu.ImageName, "versions_count", len(sourceImages))
8094
if err := iu.Provider.Configure(cpSpec, sourceImages); err != nil {
95+
iu.Log.Error(err, "provider Configure failed", "image", iu.ImageName, "error_msg", err.Error())
8196
return fmt.Errorf("failed to invoke provider: %w", err)
8297
}
98+
iu.Log.Info("provider Configure succeeded", "image", iu.ImageName)
8399
}
100+
iu.Log.Info("finished updating CloudProfile for image", "image", iu.ImageName, "total_versions", len(image.Versions))
84101
return nil
85102
}

‎controllers/managedcloudprofile_controller.go‎

Lines changed: 84 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,8 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Resu
5555
return ctrl.Result{}, client.IgnoreNotFound(err)
5656
}
5757

58+
log.Info("starting reconciliation", "ManagedCloudProfile", mcp.Name, "generation", mcp.Generation)
59+
5860
if err := r.reconcileCloudProfile(ctx, log, &mcp); err != nil {
5961
return ctrl.Result{}, err
6062
}
@@ -69,66 +71,86 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Resu
6971
func (r *Reconciler) reconcileCloudProfile(ctx context.Context, log logr.Logger, mcp *v1alpha1.ManagedCloudProfile) error {
7072
var cloudProfile gardenerv1beta1.CloudProfile
7173
cloudProfile.Name = mcp.Name
74+
log.V(1).Info("starting CloudProfile reconciliation", "name", cloudProfile.Name, "generation", mcp.Generation)
7275

7376
op, err := controllerutil.CreateOrPatch(ctx, r.Client, &cloudProfile, func() error {
74-
err := controllerutil.SetControllerReference(mcp, &cloudProfile, r.Scheme())
75-
if err != nil {
77+
if err := controllerutil.SetControllerReference(mcp, &cloudProfile, r.Scheme()); err != nil {
78+
log.Error(err, "failed to set controller reference")
7679
return err
7780
}
81+
log.V(1).Info("controller reference set")
7882
cloudProfile.Spec = CloudProfileSpecToGardener(&mcp.Spec.CloudProfile)
83+
log.V(1).Info("converted ManagedCloudProfile spec to CloudProfileSpec", "machineImages", len(cloudProfile.Spec.MachineImages))
7984
errs := make([]error, 0)
8085
for _, updates := range mcp.Spec.MachineImageUpdates {
81-
errs = append(errs, r.updateMachineImages(ctx, log, updates, &cloudProfile.Spec))
86+
log.V(1).Info("updating machine images from source", "imageName", updates.ImageName)
87+
if updateErr := r.updateMachineImages(ctx, log, updates, &cloudProfile.Spec); updateErr != nil {
88+
log.Error(updateErr, "failed to update machine images", "imageName", updates.ImageName)
89+
errs = append(errs, updateErr)
90+
}
8291
}
8392
gardenerv1beta1.SetObjectDefaults_CloudProfile(&cloudProfile)
93+
log.V(1).Info("set CloudProfile defaults")
8494
return errors.Join(errs...)
8595
})
8696
if err != nil {
87-
if err := r.patchStatusAndCondition(ctx, mcp, v1alpha1.FailedReconcileStatus, metav1.Condition{
97+
statusErr := r.patchStatusAndCondition(ctx, mcp, v1alpha1.FailedReconcileStatus, metav1.Condition{
8898
Type: CloudProfileAppliedConditionType,
8999
Status: metav1.ConditionFalse,
90100
ObservedGeneration: mcp.Generation,
91101
Reason: "ApplyFailed",
92102
Message: fmt.Sprintf("Failed to apply CloudProfile: %s", err),
93-
}); err != nil {
94-
return fmt.Errorf("failed to patch ManagedCloudProfile status: %w", err)
103+
})
104+
if statusErr != nil {
105+
log.Error(statusErr, "failed to patch ManagedCloudProfile status")
106+
return fmt.Errorf("failed to patch ManagedCloudProfile status: %w", statusErr)
95107
}
96108
if apierrors.IsInvalid(err) {
97-
log.Error(err, "tried to apply invalid CloudProfile")
109+
log.Error(err, "CloudProfile invalid, skipping apply")
98110
return nil
99111
}
112+
log.Error(err, "failed to create or patch CloudProfile")
100113
return fmt.Errorf("failed to create or patch CloudProfile: %w", err)
101114
}
102115
log.Info("applied cloud profile", "op", op)
103116
if op != controllerutil.OperationResultNone {
104-
if err := r.patchStatusAndCondition(ctx, mcp, v1alpha1.SucceededReconcileStatus, metav1.Condition{
117+
statusErr := r.patchStatusAndCondition(ctx, mcp, v1alpha1.SucceededReconcileStatus, metav1.Condition{
105118
Type: CloudProfileAppliedConditionType,
106119
Status: metav1.ConditionTrue,
107120
ObservedGeneration: mcp.Generation,
108121
Reason: "Applied",
109122
Message: "Generated CloudProfile applied successfully",
110-
}); err != nil {
111-
return fmt.Errorf("failed to patch ManagedCloudProfile status: %w", err)
123+
})
124+
if statusErr != nil {
125+
log.Error(statusErr, "failed to patch ManagedCloudProfile status after apply")
126+
return fmt.Errorf("failed to patch ManagedCloudProfile status: %w", statusErr)
112127
}
128+
log.V(1).Info("ManagedCloudProfile status updated to SucceededReconcileStatus")
113129
}
130+
log.V(1).Info("finished CloudProfile reconciliation", "name", cloudProfile.Name)
114131
return nil
115132
}
116133

117134
func (r *Reconciler) reconcileGarbageCollection(ctx context.Context, log logr.Logger, mcp *v1alpha1.ManagedCloudProfile) error {
135+
log.V(1).Info("starting garbage collection", "ManagedCloudProfile", mcp.Name)
118136
if mcp.Spec.GarbageCollection == nil || !mcp.Spec.GarbageCollection.Enabled {
137+
log.V(1).Info("garbage collection disabled or not configured")
119138
return nil
120139
}
121140
if mcp.Spec.GarbageCollection.MaxAge.Duration < 0 {
122141
return r.failWithStatusUpdate(ctx, mcp, fmt.Errorf("invalid garbage collection maxAge: %s", mcp.Spec.GarbageCollection.MaxAge.String()))
123142
}
124143

125144
cutoff := time.Now().Add(-mcp.Spec.GarbageCollection.MaxAge.Duration)
145+
log.V(1).Info("garbage collection cutoff time calculated", "cutoff", cutoff)
126146

127147
for _, updates := range mcp.Spec.MachineImageUpdates {
128148
if updates.Source.OCI == nil {
149+
log.V(1).Info("skipping update with no OCI source", "image", updates.ImageName)
129150
continue
130151
}
131152

153+
log.V(1).Info("fetching OCI credentials", "image", updates.ImageName)
132154
password, err := r.getCredential(ctx, updates.Source.OCI.Password)
133155
if err != nil {
134156
return r.failWithStatusUpdate(ctx, mcp, fmt.Errorf("failed to get credential for garbage collection: %w", err))
@@ -145,30 +167,37 @@ func (r *Reconciler) reconcileGarbageCollection(ctx context.Context, log logr.Lo
145167
return r.failWithStatusUpdate(ctx, mcp, fmt.Errorf("failed to initialize OCI source for garbage collection: %w", err))
146168
}
147169

170+
log.V(1).Info("retrieving source versions", "image", updates.ImageName)
148171
versions, err := src.GetVersions(ctx)
149172
if err != nil {
150173
return r.failWithStatusUpdate(ctx, mcp, fmt.Errorf("failed to list source versions for garbage collection: %w", err))
151174
}
175+
log.V(1).Info("retrieved source versions", "count", len(versions), "image", updates.ImageName)
152176

153-
referencedVersions, err := r.getReferencedVersions(ctx, mcp.Name, updates.ImageName)
177+
referencedVersions, err := r.getReferencedVersions(ctx, mcp.Name, updates.ImageName, log)
154178
if err != nil {
155179
return r.failWithStatusUpdate(ctx, mcp, fmt.Errorf("failed to determine referenced versions for garbage collection: %w", err))
156180
}
181+
log.V(1).Info("referenced versions retrieved", "count", len(referencedVersions), "image", updates.ImageName)
157182

158183
versionsToDelete := make(map[string]struct{})
159184
for _, v := range versions {
160185
if v.CreatedAt.IsZero() {
186+
log.V(1).Info("skipping version with zero CreatedAt", "version", v.Version)
161187
continue
162188
}
163189
if _, isReferenced := referencedVersions[v.Version]; isReferenced {
190+
log.V(2).Info("skipping referenced version", "version", v.Version)
164191
continue
165192
}
166193
if v.CreatedAt.Before(cutoff) {
167194
versionsToDelete[v.Version] = struct{}{}
195+
log.V(1).Info("marking version for deletion", "version", v.Version)
168196
}
169197
}
170198

171199
if len(versionsToDelete) > 0 {
200+
log.V(1).Info("deleting versions from CloudProfile", "image", updates.ImageName, "count", len(versionsToDelete))
172201
if err := r.deleteVersions(ctx, mcp.Name, updates.ImageName, versionsToDelete); err != nil {
173202
if apierrors.IsInvalid(err) {
174203
log.V(1).Info("garbage collection validation failed, skipping", "image", updates.ImageName)
@@ -179,66 +208,92 @@ func (r *Reconciler) reconcileGarbageCollection(ctx context.Context, log logr.Lo
179208
for v := range versionsToDelete {
180209
log.Info("deleted image version from CloudProfile", "image", updates.ImageName, "version", v)
181210
}
211+
} else {
212+
log.V(1).Info("no versions to delete for image", "image", updates.ImageName)
182213
}
183214
}
184215

216+
log.V(1).Info("completed garbage collection", "ManagedCloudProfile", mcp.Name)
185217
return nil
186218
}
187219

188220
func (r *Reconciler) deleteVersions(ctx context.Context, cloudProfileName, imageName string, versionsToDelete map[string]struct{}) error {
221+
log := ctrl.LoggerFrom(ctx)
222+
log.V(1).Info("starting deleteVersions", "cloudProfile", cloudProfileName, "image", imageName, "versionsToDelete", versionsToDelete)
189223
var cp gardenerv1beta1.CloudProfile
190224
if err := r.Get(ctx, types.NamespacedName{Name: cloudProfileName}, &cp); err != nil {
225+
log.Error(err, "failed to get CloudProfile")
191226
return err
192227
}
193228

194229
for i := range cp.Spec.MachineImages {
195230
if cp.Spec.MachineImages[i].Name != imageName {
196231
continue
197232
}
233+
originalCount := len(cp.Spec.MachineImages[i].Versions)
198234
cp.Spec.MachineImages[i].Versions = slices.DeleteFunc(cp.Spec.MachineImages[i].Versions, func(mv gardenerv1beta1.MachineImageVersion) bool {
199235
_, exists := versionsToDelete[mv.Version]
236+
if exists {
237+
log.V(1).Info("removing version from CloudProfile MachineImages", "version", mv.Version)
238+
}
200239
return exists
201240
})
241+
log.V(1).Info("updated CloudProfile MachineImages versions", "original", originalCount, "remaining", len(cp.Spec.MachineImages[i].Versions))
202242
}
203243
if cp.Spec.ProviderConfig != nil {
204244
var cfg providercfg.CloudProfileConfig
205245
if err := json.Unmarshal(cp.Spec.ProviderConfig.Raw, &cfg); err != nil {
246+
log.Error(err, "failed to unmarshal ProviderConfig")
206247
return fmt.Errorf("failed to unmarshal ProviderConfig: %w", err)
207248
}
208249
for i := range cfg.MachineImages {
209250
if cfg.MachineImages[i].Name != imageName {
210251
continue
211252
}
253+
originalCount := len(cfg.MachineImages[i].Versions)
212254
cfg.MachineImages[i].Versions = slices.DeleteFunc(cfg.MachineImages[i].Versions, func(mv providercfg.MachineImageVersion) bool {
213255
idx := strings.LastIndex(mv.Image, ":")
214256
if idx == -1 {
215257
return false
216258
}
217259
version := mv.Image[idx+1:]
218260
_, exists := versionsToDelete[version]
261+
if exists {
262+
log.V(1).Info("removing version from ProviderConfig", "version", version, "imageRef", mv.Image)
263+
}
219264
return exists
220265
})
266+
log.V(1).Info("updated ProviderConfig MachineImages versions", "original", originalCount, "remaining", len(cfg.MachineImages[i].Versions))
221267
}
222268
raw, err := json.Marshal(cfg)
223269
if err != nil {
270+
log.Error(err, "failed to marshal ProviderConfig after deletion")
224271
return fmt.Errorf("failed to marshal ProviderConfig: %w", err)
225272
}
226273
cp.Spec.ProviderConfig.Raw = raw
227274
}
228-
229-
return r.Update(ctx, &cp)
275+
if err := r.Update(ctx, &cp); err != nil {
276+
log.Error(err, "failed to update CloudProfile after deleting versions")
277+
return err
278+
}
279+
log.V(1).Info("finished deleteVersions successfully")
280+
return nil
230281
}
231282

232-
func (r *Reconciler) getReferencedVersions(ctx context.Context, cloudProfileName, imageName string) (map[string]struct{}, error) {
283+
func (r *Reconciler) getReferencedVersions(ctx context.Context, cloudProfileName, imageName string, log logr.Logger) (map[string]struct{}, error) {
233284
referenced := make(map[string]struct{})
285+
log.V(1).Info("retrieving referenced versions", "cloudProfile", cloudProfileName, "image", imageName)
234286

235287
var cp gardenerv1beta1.CloudProfile
236288
if err := r.Get(ctx, types.NamespacedName{Name: cloudProfileName}, &cp); err != nil {
289+
log.Error(err, "failed to get CloudProfile")
237290
return nil, fmt.Errorf("failed to get CloudProfile: %w", err)
238291
}
292+
239293
if cp.Spec.ProviderConfig != nil {
240294
var cfg providercfg.CloudProfileConfig
241295
if err := json.Unmarshal(cp.Spec.ProviderConfig.Raw, &cfg); err != nil {
296+
log.Error(err, "failed to unmarshal ProviderConfig")
242297
return nil, fmt.Errorf("failed to unmarshal ProviderConfig: %w", err)
243298
}
244299
for _, img := range cfg.MachineImages {
@@ -249,13 +304,15 @@ func (r *Reconciler) getReferencedVersions(ctx context.Context, cloudProfileName
249304
if idx := strings.LastIndex(v.Image, ":"); idx != -1 {
250305
version := v.Image[idx+1:]
251306
referenced[version] = struct{}{}
307+
log.V(2).Info("found referenced version in ProviderConfig", "version", version)
252308
}
253309
}
254310
}
255311
}
256312

257313
shootList := &gardenerv1beta1.ShootList{}
258314
if err := r.List(ctx, shootList, client.InNamespace(metav1.NamespaceAll)); err != nil {
315+
log.Error(err, "failed to list Shoots")
259316
return nil, fmt.Errorf("failed to list Shoots: %w", err)
260317
}
261318
for _, shoot := range shootList.Items {
@@ -269,19 +326,24 @@ func (r *Reconciler) getReferencedVersions(ctx context.Context, cloudProfileName
269326
}
270327
if worker.Machine.Image.Version != nil {
271328
referenced[*worker.Machine.Image.Version] = struct{}{}
329+
log.V(2).Info("found referenced version in Shoot", "shoot", shoot.Name, "worker", worker.Name, "version", *worker.Machine.Image.Version)
272330
}
273331
}
274332
}
275333

334+
log.V(1).Info("completed retrieval of referenced versions", "count", len(referenced))
276335
return referenced, nil
277336
}
278337

279338
func (r *Reconciler) updateMachineImages(ctx context.Context, log logr.Logger, update v1alpha1.MachineImageUpdate, cpSpec *gardenerv1beta1.CloudProfileSpec) error {
339+
log.Info("updating machine images", "imageName", update.ImageName)
280340
var source cloudprofilesync.Source
281341
switch {
282342
case update.Source.OCI != nil:
343+
log.V(1).Info("using OCI source", "registry", update.Source.OCI.Registry, "repository", update.Source.OCI.Repository)
283344
password, err := r.getCredential(ctx, update.Source.OCI.Password)
284345
if err != nil {
346+
log.Error(err, "failed to get credentials for OCI source", "imageName", update.ImageName)
285347
return err
286348
}
287349
src, err := r.OCISourceFactory.Create(cloudprofilesync.OCIParams{
@@ -292,15 +354,19 @@ func (r *Reconciler) updateMachineImages(ctx context.Context, log logr.Logger, u
292354
Parallel: 1,
293355
}, update.Source.OCI.Insecure)
294356
if err != nil {
295-
return fmt.Errorf("failed to initialize oci source: %w", err)
357+
log.Error(err, "failed to initialize OCI source", "imageName", update.ImageName)
358+
return fmt.Errorf("failed to initialize OCI source: %w", err)
296359
}
297360
source = src
361+
298362
default:
363+
log.Error(nil, "no machine images source configured", "imageName", update.ImageName)
299364
return errors.New("no machine images source configured")
300365
}
301366

302367
var provider cloudprofilesync.Provider
303368
if update.Provider.IroncoreMetal != nil {
369+
log.V(1).Info("using provider IroncoreMetal", "registry", update.Provider.IroncoreMetal.Registry, "repository", update.Provider.IroncoreMetal.Repository)
304370
provider = &cloudprofilesync.IroncoreProvider{
305371
Registry: update.Provider.IroncoreMetal.Registry,
306372
Repository: update.Provider.IroncoreMetal.Repository,
@@ -313,9 +379,12 @@ func (r *Reconciler) updateMachineImages(ctx context.Context, log logr.Logger, u
313379
Provider: provider,
314380
ImageName: update.ImageName,
315381
}
382+
log.V(1).Info("calling ImageUpdater.Update", "imageName", update.ImageName)
316383
if err := imageUpdater.Update(ctx, cpSpec); err != nil {
384+
log.Error(err, "ImageUpdater.Update failed", "imageName", update.ImageName)
317385
return fmt.Errorf("updating machine images failed: %w", err)
318386
}
387+
log.Info("successfully updated machine images", "imageName", update.ImageName)
319388
return nil
320389
}
321390

0 commit comments

Comments
 (0)