Logging Improvements (#460)

* Add API start logs

* fix comment

* adding operation stage logging for each subcomponent

* switching to k8sname where logical

* Apply suggestions from code review

Co-authored-by: Liam Fallon <35595825+liamfallon@users.noreply.github.com>

* amending comments + only utilizing FromFullPathname function after OpenRepository function to avoid invalid memory address test failing on TestCreatePRWith2Tasks

* fixing test case occuring in DeletePR operation due gitPR2Del asserting nil for key

* adding unit tests for registry/packagerevision.go Get/Create/Delete functions

* addressing comments

* moving API operation start logs after validation of operation occurs + removing wasteful variable defenitions

* fixed malformed k8s names

* adding unit test for Get(pkgrevres) & Update(pkgcommon)

* nitpick change to rerun tests

---------

Co-authored-by: Kushal Harish Naidu <kushal.harish.naidu@ericsson.com>
Co-authored-by: Liam Fallon <35595825+liamfallon@users.noreply.github.com>

Author: 3 people

pkg/cache/crcache/repository.go

@@ -112,6 +112,11 @@ func (r *cachedRepository) Version(ctx context.Context) (string, error) {
 }
 
 func (r *cachedRepository) ListPackageRevisions(ctx context.Context, filter repository.ListPackageRevisionFilter) ([]repository.PackageRevision, error) {
+	klog.V(3).Infof("[CR Cache] Retrieving cached package revisions and enriching with PackageRev CR metadata from etcd for repository: %s", r.Key())
+	defer func() {
+		klog.V(3).Infof("[CR Cache] Completed retrieving and enriching package revisions with PackageRev CR metadata for repository: %s", r.Key())
+	}()
+
 	packages, err := r.getPackageRevisions(ctx, filter, false)
 	if err != nil {
 		return nil, err
@@ -206,13 +211,28 @@ func (r *cachedRepository) getCachedPackages(ctx context.Context, forceRefresh b
 }
 
 func (r *cachedRepository) CreatePackageRevisionDraft(ctx context.Context, obj *porchapi.PackageRevision) (repository.PackageRevisionDraft, error) {
+	pkgRevKey := repository.PackageRevisionKey{
+		PkgKey:        repository.FromFullPathname(r.Key(), obj.Spec.PackageName),
+		Revision:      0,
+		WorkspaceName: obj.Spec.WorkspaceName,
+	}
+	klog.Infof("[CR Cache] Creating draft and preparing to save to Git for PackageRevision: %s", pkgRevKey.K8SName())
+	defer func() {
+		klog.V(3).Infof("[CR Cache] Draft created and saved to Git for PackageRevision: %s", pkgRevKey.K8SName())
+	}()
+
 	return r.repo.CreatePackageRevisionDraft(ctx, obj)
 }
 
 func (r *cachedRepository) ClosePackageRevisionDraft(ctx context.Context, prd repository.PackageRevisionDraft, version int) (repository.PackageRevision, error) {
 	ctx, span := tracer.Start(ctx, "cachedRepository::ClosePackageRevisionDraft", trace.WithAttributes())
 	defer span.End()
 
+	klog.Infof("[CR Cache] Closing draft and pushing lifecycle change to Git for PackageRevision: %s", prd.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[CR Cache] Draft closed and lifecycle change pushed to Git for PackageRevision: %s", prd.Key().K8SName())
+	}()
+
 	v, err := r.Version(ctx)
 	if err != nil {
 		return nil, err
@@ -279,6 +299,11 @@ func (r *cachedRepository) ClosePackageRevisionDraft(ctx context.Context, prd re
 }
 
 func (r *cachedRepository) UpdatePackageRevision(ctx context.Context, old repository.PackageRevision) (repository.PackageRevisionDraft, error) {
+	klog.Infof("[CR Cache] Loading draft for update from Git for PackageRevision: %s", old.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[CR Cache] Draft loaded and ready for modifications for PackageRevision: %s", old.Key().K8SName())
+	}()
+
 	// Unwrap
 	unwrapped := old.(*cachedPackageRevision).PackageRevision
 
@@ -396,6 +421,11 @@ func (r *cachedRepository) DeletePackageRevision(ctx context.Context, prToDelete
 	// terminating state.
 	// But we only delete the PackageRevision from the repo once all finalizers
 	// have been removed.
+	klog.Infof("[CR Cache] Deleting PackageRev CR from etcd and branch from Git for PackageRevision: %s", prToDelete.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[CR Cache] PackageRev CR and Git branch deleted for PackageRevision: %s", prToDelete.Key().K8SName())
+	}()
+
 	namespacedName := types.NamespacedName{
 		Name:      prToDelete.KubeObjectName(),
 		Namespace: prToDelete.KubeObjectNamespace(),

pkg/cache/dbcache/dbpackagerevision.go

@@ -128,6 +128,20 @@ func (pr *dbPackageRevision) UpdateLifecycle(ctx context.Context, newLifecycle p
 	if pr.repo == nil {
 		return fmt.Errorf("cannot update lifecycle for package revision %s: no associated repository", pr.KubeObjectName())
 	}
+	
+	// Only Approve (Proposed → Published) pushes to external repo
+	// TODO should be replaced with flag when option for db-cache push to git regardless PR comes in
+	if pr.lifecycle == porchapi.PackageRevisionLifecycleProposed && newLifecycle == porchapi.PackageRevisionLifecyclePublished {
+		klog.Infof("[DB Cache] Updating lifecycle in database and pushing to external repo for PackageRevision: %s", pr.Key().K8SName())
+		defer func() {
+			klog.V(3).Infof("[DB Cache] Lifecycle updated in database and pushed to external repo for PackageRevision: %s", pr.Key().K8SName())
+		}()
+	} else {
+		klog.Infof("[DB Cache] Updating lifecycle in database for PackageRevision: %s", pr.Key().K8SName())
+		defer func() {
+			klog.V(3).Infof("[DB Cache] Lifecycle updated in database for PackageRevision: %s", pr.Key().K8SName())
+		}()
+	}
 
 	if pr.lifecycle == porchapi.PackageRevisionLifecycleProposed && newLifecycle == porchapi.PackageRevisionLifecyclePublished {
 		if err := pr.publishPR(ctx, newLifecycle); err != nil {
@@ -395,6 +409,11 @@ func (pr *dbPackageRevision) UpdateResources(ctx context.Context, new *porchapi.
 	_, span := tracer.Start(ctx, "dbPackageRevision::UpdateResources", trace.WithAttributes())
 	defer span.End()
 
+	klog.Infof("[DB Cache] Updating resources in memory for PackageRevision: %s", pr.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[DB Cache] Resources updated in memory for PackageRevision: %s", pr.Key().K8SName())
+	}()
+
 	pr.resources = new.Spec.Resources
 
 	if change != nil && porchapi.IsValidFirstTaskType(change.Type) {

pkg/cache/dbcache/dbrepository.go

@@ -137,6 +137,11 @@ func (r *dbRepository) ListPackageRevisions(ctx context.Context, filter reposito
 	ctx, span := tracer.Start(ctx, "dbRepository::ListPackageRevisions", trace.WithAttributes())
 	defer span.End()
 
+	klog.V(3).Infof("[DB Cache] Retrieving PackageRevisions from database for repository: %s", r.Key())
+	defer func() {
+		klog.V(3).Infof("[DB Cache] Completed retrieving PackageRevisions from database for repository: %s", r.Key())
+	}()
+
 	klog.V(5).Infof("ListPackageRevisions: listing package revisions in repository %+v with filter %+v", r.Key(), filter)
 
 	filter.Key.PkgKey.RepoKey = r.Key()
@@ -170,6 +175,17 @@ func (r *dbRepository) CreatePackageRevisionDraft(ctx context.Context, newPR *po
 	ctx, span := tracer.Start(ctx, "dbRepository::CreatePackageRevisionDraft", trace.WithAttributes())
 	defer span.End()
 
+	pkgRevKey := repository.PackageRevisionKey{
+		PkgKey:        repository.FromFullPathname(r.Key(), newPR.Spec.PackageName),
+		Revision:      0,
+		WorkspaceName: newPR.Spec.WorkspaceName,
+	}
+	pkgKey := pkgRevKey.K8SName()
+	klog.Infof("[DB Cache] Creating database entry for draft object for PackageRevision: %s", pkgKey)
+	defer func() {
+		klog.V(3).Infof("[DB Cache] Database entry for draft object created for PackageRevision: %s", pkgKey)
+	}()
+
 	klog.V(5).Infof("dbRepository:CreatePackageRevisionDraft: creating draft for %+v on repo %+v", newPR, r.Key())
 
 	if newPR.CreationTimestamp.Time.IsZero() {
@@ -214,6 +230,20 @@ func (r *dbRepository) DeletePackageRevision(ctx context.Context, pr2Delete repo
 	ctx, span := tracer.Start(ctx, "dbRepository::DeletePackageRevision", trace.WithAttributes())
 	defer span.End()
 
+	// Only published packages are deleted from external repo
+	// TODO should be replaced with flag when option for db-cache push to git regardless PR comes in
+	if porchapi.LifecycleIsPublished(pr2Delete.Lifecycle(context.Background())) {
+		klog.Infof("[DB Cache] Deleting PackageRevision from database and external repo for PackageRevision: %s", pr2Delete.Key().K8SName())
+		defer func() {
+			klog.V(3).Infof("[DB Cache] PackageRevision deleted from database and external repo for PackageRevision: %s", pr2Delete.Key().K8SName())
+		}()
+	} else {
+		klog.Infof("[DB Cache] Deleting PackageRevision from database for PackageRevision: %s", pr2Delete.Key().K8SName())
+		defer func() {
+			klog.V(3).Infof("[DB Cache] PackageRevision deleted from database for PackageRevision: %s", pr2Delete.Key().K8SName())
+		}()
+	}
+
 	if len(pr2Delete.GetMeta().Finalizers) > 0 {
 		klog.V(5).Infof("dbRepository:DeletePackageRevision: deletion ordered on package revision %+v on repo %+v, but finalizers %+v exist", pr2Delete.Key(), r.Key(), pr2Delete.GetMeta().Finalizers)
 
@@ -270,6 +300,11 @@ func (r *dbRepository) UpdatePackageRevision(ctx context.Context, updatePR repos
 	ctx, span := tracer.Start(ctx, "dbRepository::UpdatePackageRevision", trace.WithAttributes())
 	defer span.End()
 
+	klog.Infof("[DB Cache] Loading draft from database for update for PackageRevision: %s", updatePR.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[DB Cache] Draft loaded from database and ready for modifications for PackageRevision: %s", updatePR.Key().K8SName())
+	}()
+
 	klog.V(5).Infof("dbRepository:UpdatePackageRevision: updating package revision %+v on repo %+v", updatePR.Key(), r.Key())
 
 	updatePkgRev, ok := updatePR.(*dbPackageRevision)
@@ -321,6 +356,12 @@ func (r *dbRepository) ClosePackageRevisionDraft(ctx context.Context, prd reposi
 	_, span := tracer.Start(ctx, "dbRepository::ClosePackageRevisionDraft", trace.WithAttributes())
 	defer span.End()
 
+	d := prd.(*dbPackageRevision)
+	klog.Infof("[DB Cache] Saving PackageRevision to database for PackageRevision: %s", d.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[DB Cache] PackageRevision saved to database for PackageRevision: %s", d.Key().K8SName())
+	}()
+
 	pr, err := r.savePackageRevisionDraft(ctx, prd, version)
 
 	return repository.PackageRevision(pr), err

pkg/engine/engine.go

@@ -94,6 +94,11 @@ func (cad *cadEngine) ListPackageRevisions(ctx context.Context, repositorySpec *
 	ctx, span := tracer.Start(ctx, "cadEngine::ListPackageRevisions", trace.WithAttributes())
 	defer span.End()
 
+	klog.V(3).Infof("[CaD Engine] Opening cached repository for listing: %s", repositorySpec.Name)
+	defer func() {
+		klog.V(3).Infof("[CaD Engine] Completed listing from cached repository: %s", repositorySpec.Name)
+	}()
+
 	repo, err := cad.cache.OpenRepository(ctx, repositorySpec)
 	if err != nil {
 		return nil, err
@@ -148,6 +153,11 @@ func (cad *cadEngine) CreatePackageRevision(ctx context.Context, repositoryObj *
 	}
 
 	pkgKey := repository.FromFullPathname(repo.Key(), newPr.Spec.PackageName)
+	klog.Infof("[CaD Engine] Validating and preparing package creation for PackageRevision: %s.%s", pkgKey.K8SName(), newPr.Spec.WorkspaceName)
+	defer func() {
+		klog.V(3).Infof("[CaD Engine] Package creation delegated to cache for PackageRevision: %s.%s", pkgKey.K8SName(), newPr.Spec.WorkspaceName)
+	}()
+
 	if err := util.ValidPkgRevObjName(repositoryObj.Name, pkgKey.Path, pkgKey.Package, newPr.Spec.WorkspaceName); err != nil {
 		return nil, fmt.Errorf("failed to create packagerevision: %w", err)
 	}
@@ -298,6 +308,11 @@ func (cad *cadEngine) UpdatePackageRevision(ctx context.Context, version int, re
 		return nil, err
 	}
 
+	klog.Infof("[CaD Engine] Processing lifecycle change and preparing update for PackageRevision: %s", repoPr.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[CaD Engine] Lifecycle change processed and delegated to cache for PackageRevision: %s", repoPr.Key().K8SName())
+	}()
+
 	// Check if the PackageRevision is in the terminating state and
 	// and this request removes the last finalizer.
 	repoPkgRev := repoPr
@@ -402,6 +417,11 @@ func (cad *cadEngine) DeletePackageRevision(ctx context.Context, repositoryObj *
 	ctx, span := tracer.Start(ctx, "cadEngine::DeletePackageRevision", trace.WithAttributes())
 	defer span.End()
 
+	klog.Infof("[CaD Engine] Preparing to delete PackageRevision: %s", pr2Del.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[CaD Engine] PackageRevision deletion delegated to cache: %s", pr2Del.Key().K8SName())
+	}()
+
 	repo, err := cad.cache.OpenRepository(ctx, repositoryObj)
 	if err != nil {
 		return err
@@ -444,6 +464,12 @@ func (cad *cadEngine) UpdatePackageResources(ctx context.Context, repositoryObj
 	ctx, span := tracer.Start(ctx, "cadEngine::UpdatePackageResources", trace.WithAttributes())
 	defer span.End()
 
+	pkgKey := pr2Update.Key().K8SName()
+	klog.Infof("[CaD Engine] Processing resource updates for PackageRevision: %s", pkgKey)
+	defer func() {
+		klog.V(3).Infof("[CaD Engine] Resource updates processed and delegated to cache for PackageRevision: %s", pkgKey)
+	}()
+
 	rev, err := pr2Update.GetPackageRevision(ctx)
 	if err != nil {
 		return nil, nil, err

pkg/externalrepo/git/git.go

@@ -435,6 +435,15 @@ func (r *gitRepository) CreatePackageRevisionDraft(ctx context.Context, obj *por
 	_, span := tracer.Start(ctx, "gitRepository::CreatePackageRevisionDraft", trace.WithAttributes())
 	defer span.End()
 
+	pkgKey := repository.FromFullPathname(r.Key(), obj.Spec.PackageName)
+	if err := util.ValidPkgRevObjName(r.Key().Name, pkgKey.Path, pkgKey.Package, obj.Spec.WorkspaceName); err != nil {
+		return nil, fmt.Errorf("failed to create packagerevision: %w", err)
+	}
+	klog.Infof("[Git] Creating in-memory draft object started for PackageRevision: %s", pkgKey.K8SName())
+	defer func() {
+		klog.V(3).Infof("[Git] Creating in-memory draft object completed for PackageRevision: %s", pkgKey.K8SName())
+	}()
+
 	var base plumbing.Hash
 	refName := r.branch.RefInLocal()
 	err := r.sharedDir.WithRLock(func(repo *git.Repository) error {
@@ -453,11 +462,6 @@ func (r *gitRepository) CreatePackageRevisionDraft(ctx context.Context, obj *por
 		return nil, err
 	}
 
-	pkgKey := repository.FromFullPathname(r.Key(), obj.Spec.PackageName)
-	if err := util.ValidPkgRevObjName(r.Key().Name, pkgKey.Path, pkgKey.Package, obj.Spec.WorkspaceName); err != nil {
-		return nil, fmt.Errorf("failed to create packagerevision: %w", err)
-	}
-
 	draftKey := repository.PackageRevisionKey{
 		PkgKey:        pkgKey,
 		WorkspaceName: obj.Spec.WorkspaceName,
@@ -490,6 +494,11 @@ func (r *gitRepository) UpdatePackageRevision(ctx context.Context, old repositor
 		return nil, fmt.Errorf("cannot update non-git package %T", old)
 	}
 
+	klog.Infof("[Git] Loading draft for update started for PackageRevision: %s", old.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[Git] Loading draft for update completed for PackageRevision: %s", old.Key().K8SName())
+	}()
+
 	ref := oldGitPackage.ref
 	if ref == nil {
 		return nil, fmt.Errorf("cannot update final package")
@@ -546,6 +555,10 @@ func (r *gitRepository) DeletePackageRevision(ctx context.Context, pr2Delete rep
 			referenceName = ""
 		}
 	}
+	klog.Infof("[Git] Deleting branch from Git repository started for PackageRevision: %s", pr2Delete.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[Git] Deleting branch from Git repository completed for PackageRevision: %s", pr2Delete.Key().K8SName())
+	}()
 
 	if referenceName == "" {
 		// This is an internal error. In some rare cases (see GetPackageRevision below) we create
@@ -1371,6 +1384,11 @@ func (r *gitRepository) pushAndCleanup(ctx context.Context, ph *pushRefSpecBuild
 	ctx, span := tracer.Start(ctx, "gitRepository::pushAndCleanup", trace.WithAttributes())
 	defer span.End()
 
+	klog.Infof("[Git] Pushing changes to remote Git repository %s started", r.key.Name)
+	defer func() {
+		klog.V(3).Infof("[Git] Pushing changes to remote Git repository %s completed", r.key.Name)
+	}()
+
 	maxRetries := r.repoOperationRetryAttempts
 	for attempt := 1; attempt <= maxRetries; attempt++ {
 		if err := r.doGitWithAuth(ctx, func(auth transport.AuthMethod) error {
@@ -1676,6 +1694,11 @@ func (r *gitRepository) UpdateLifecycle(ctx context.Context, pkgRev *gitPackageR
 	ctx, span := tracer.Start(ctx, "gitRepository::UpdateLifecycle", trace.WithAttributes())
 	defer span.End()
 
+	klog.Infof("[Git] Updating lifecycle from %s to %s started for PackageRevision:  %s", pkgRev.Lifecycle(ctx), newLifecycle, pkgRev.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[Git] Updating lifecycle from %s to %s completed for PackageRevision: %s", pkgRev.Lifecycle(ctx), newLifecycle, pkgRev.Key().K8SName())
+	}()
+
 	r.mutex.Lock()
 	old := r.getLifecycle(pkgRev)
 	if !porchapi.LifecycleIsPublished(old) {
@@ -1784,6 +1807,10 @@ func (r *gitRepository) ClosePackageRevisionDraft(ctx context.Context, prd repos
 	defer span.End()
 
 	d := prd.(*gitPackageRevisionDraft)
+	klog.Infof("[Git] Changing lifecycle to %s and pushing to Git started for PackageRevision: %s", d.lifecycle, d.Key().K8SName())
+	defer func() {
+		klog.V(3).Infof("[Git] Changing lifecycle to %s and pushing to Git completed for PackageRevision: %s", d.lifecycle, d.Key().K8SName())
+	}()
 
 	refSpecs := newPushRefSpecBuilder()
 	commitOps := NewCommitOperationBuilder()

pkg/registry/porch/packagecommon.go

@@ -327,6 +327,7 @@ func (r *packageCommon) updatePackageRevision(ctx context.Context, name string,
 	defer span.End()
 
 	// TODO: Is this all boilerplate??
+	klog.V(3).Infof("PackageRevision update validation started: %s", name)
 
 	namespace, namespaced := genericapirequest.NamespaceFrom(ctx)
 	if !namespaced {
@@ -394,6 +395,15 @@ func (r *packageCommon) updatePackageRevision(ctx context.Context, name string,
 		return nil, false, apierrors.NewBadRequest(fmt.Sprintf("expected PackageRevision object, got %T", newRuntimeObj))
 	}
 
+	klog.V(3).Infof("PackageRevision update validation completed: %s", name)
+
+	if oldApiPkgRev != nil {
+		action := getLifecycleTransition(oldApiPkgRev.(*porchapi.PackageRevision), newApiPkgRev)
+		klog.Infof("[API] %s operation started for PackageRevision: %s", action, name)
+	} else {
+		klog.Infof("[API] Update operation started for PackageRevision: %s", name)
+	}
+
 	prKey, err := repository.PkgRevK8sName2Key(namespace, name)
 	if err != nil {
 		return nil, false, err
@@ -448,7 +458,7 @@ func (r *packageCommon) updatePackageRevision(ctx context.Context, name string,
 	}
 
 	if action := getLifecycleTransition(oldApiPkgRev.(*porchapi.PackageRevision), newApiPkgRev); action != "" {
-		klog.Infof("%s operation completed for package revision: %s", action, name)
+		klog.Infof("[API] %s operation completed for PackageRevision: %s", action, name)
 	}
 
 	return updated, false, nil
@@ -478,7 +488,7 @@ func getLifecycleTransition(oldPkgRev, newPkgRev *porchapi.PackageRevision) stri
 			newPkgRev.Spec.Lifecycle == porchapi.PackageRevisionLifecyclePublished {
 			return "Approve"
 		}
-		// Approve or Reject Operation: Published -> Proposed
+		// Approve or Reject Operation: DeletionProposed -> Published
 		if oldPkgRev.Spec.Lifecycle == porchapi.PackageRevisionLifecycleDeletionProposed &&
 			newPkgRev.Spec.Lifecycle == porchapi.PackageRevisionLifecyclePublished {
 			return "Approve/Reject"