Skip to content

Commit 3e088d4

Browse files
kushnaidukushnaidu
committed
Add API start logs and Improve reduce log spam in default logs
1 parent 5f9b783 commit 3e088d4

6 files changed

Lines changed: 52 additions & 25 deletions

File tree

‎pkg/cache/crcache/repository.go‎

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -148,7 +148,12 @@ func (r *cachedRepository) getRefreshError() error {
148148
}
149149

150150
func (r *cachedRepository) getPackageRevisions(ctx context.Context, filter repository.ListPackageRevisionFilter, forceRefresh bool) ([]repository.PackageRevision, error) {
151-
klog.Infof("Cache::OpenRepository(%s) fetching packages", r.Key())
151+
if forceRefresh {
152+
klog.Infof("crcache: getPackageRevisions(%s) fetching packages from external repository", r.Key())
153+
} else {
154+
klog.V(3).Infof("crcache: getPackageRevisions(%s) using cached packages", r.Key())
155+
}
156+
152157
_, packageRevisions, err := r.getCachedPackages(ctx, forceRefresh)
153158
if err != nil {
154159
return nil, err
@@ -266,7 +271,7 @@ func (r *cachedRepository) ClosePackageRevisionDraft(ctx context.Context, prd re
266271
}
267272

268273
sent := r.repoPRChangeNotifier.NotifyPackageRevisionChange(watch.Added, cachedPr)
269-
klog.Infof("cache: sent %d for new PackageRevision %s/%s", sent, cachedPr.KubeObjectNamespace(), cachedPr.KubeObjectName())
274+
klog.Infof("crcache: sent %d for new PackageRevision %s/%s", sent, cachedPr.KubeObjectNamespace(), cachedPr.KubeObjectName())
270275
return cachedPr, nil
271276
}
272277

@@ -446,7 +451,8 @@ func (r *cachedRepository) ListPackages(ctx context.Context, filter repository.L
446451
}
447452

448453
func (r *cachedRepository) CreatePackage(ctx context.Context, obj *porchapi.PorchPackage) (repository.Package, error) {
449-
klog.Infoln("cachedRepository::CreatePackage")
454+
ctx, span := tracer.Start(ctx, "cachedRepository::CreatePackage", trace.WithAttributes())
455+
defer span.End()
450456
return r.repo.CreatePackage(ctx, obj)
451457
}
452458

‎pkg/externalrepo/git/git.go‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1068,7 +1068,7 @@ func (r *gitRepository) fetchRemoteRepository(ctx context.Context) error {
10681068
ctx, span := tracer.Start(ctx, "gitRepository::fetchRemoteRepository", trace.WithAttributes())
10691069
defer span.End()
10701070
start := time.Now()
1071-
defer func() { klog.V(4).Infof("Fetching repository %q took %s", r.key.Name, time.Since(start)) }()
1071+
defer func() { klog.V(2).Infof("Fetching repository %q took %s", r.key.Name, time.Since(start)) }()
10721072

10731073
if ctx.Err() != nil {
10741074
return ctx.Err()
@@ -1227,7 +1227,8 @@ func (r *gitRepository) pushAndCleanup(ctx context.Context, ph *pushRefSpecBuild
12271227
return err
12281228
}
12291229

1230-
klog.Infof("pushing refs: %v", specs)
1230+
pushStart := time.Now()
1231+
klog.Infof("git push: repository=%q remote=%s refs=%v", r.key.Name, OriginName, specs)
12311232

12321233
if err := r.doGitWithAuth(ctx, func(auth transport.AuthMethod) error {
12331234
return r.repo.Push(&git.PushOptions{
@@ -1247,6 +1248,7 @@ func (r *gitRepository) pushAndCleanup(ctx context.Context, ph *pushRefSpecBuild
12471248
}
12481249
return err
12491250
}
1251+
klog.Infof("git push completed: repository=%q refs=%v duration=%s", r.key.Name, specs, time.Since(pushStart))
12501252
return nil
12511253
}
12521254

‎pkg/registry/porch/background.go‎

Lines changed: 6 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -130,17 +130,17 @@ loop:
130130

131131
case event, eventOk := <-events:
132132
if !eventOk {
133-
klog.Errorf("Watch event stream closed. Will restart watch from bookmark %q", bookmark)
133+
klog.V(4).Infof("Watch event stream closed. Will restart watch from bookmark %q", bookmark)
134134
watcher.Stop()
135135
events = nil
136136
watcher = nil
137137

138-
// Initiate reconnect
139-
reconnect.reset()
138+
// Initiate reconnect with backoff
139+
reconnect.backoff()
140140
} else if repository, ok := event.Object.(*configapi.Repository); ok {
141141
if event.Type == watch.Bookmark {
142142
bookmark = repository.ResourceVersion
143-
klog.Infof("Bookmark: %q", bookmark)
143+
klog.V(2).Infof("Bookmark: %q", bookmark)
144144
} else {
145145
if err := b.updateCache(ctx, event.Type, repository); err != nil {
146146
klog.Warningf("error updating cache: %v", err)
@@ -151,7 +151,7 @@ loop:
151151
}
152152

153153
case t := <-ticker.C:
154-
klog.Infof("Background task %s", t)
154+
klog.V(2).Infof("Background task %s", t)
155155
if err := b.runOnce(ctx); err != nil {
156156
klog.Errorf("Periodic repository refresh failed: %v", err)
157157
}
@@ -227,7 +227,7 @@ func (b *background) handleRepositoryEvent(ctx context.Context, repo *configapi.
227227
}
228228

229229
func (b *background) runOnce(ctx context.Context) error {
230-
klog.Infof("background-refreshing repositories")
230+
klog.V(2).Infof("background-refreshing repositories")
231231
repositories := &configapi.RepositoryList{}
232232
if err := b.coreClient.List(ctx, repositories); err != nil {
233233
return fmt.Errorf("error listing repository objects: %w", err)
@@ -354,11 +354,6 @@ func (t *backoffTimer) channel() <-chan time.Time {
354354
return t.timer.C
355355
}
356356

357-
func (t *backoffTimer) reset() bool {
358-
t.curr = t.min
359-
return t.timer.Reset(t.curr)
360-
}
361-
362357
func (t *backoffTimer) backoff() bool {
363358
curr := t.curr * 2
364359
if curr > t.max {

‎pkg/registry/porch/packagecommon.go‎

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -327,6 +327,7 @@ func (r *packageCommon) updatePackageRevision(ctx context.Context, name string,
327327
defer span.End()
328328

329329
// TODO: Is this all boilerplate??
330+
klog.V(3).Infof("PackageRevision update validation started: %s", name)
330331

331332
namespace, namespaced := genericapirequest.NamespaceFrom(ctx)
332333
if !namespaced {
@@ -394,6 +395,15 @@ func (r *packageCommon) updatePackageRevision(ctx context.Context, name string,
394395
return nil, false, apierrors.NewBadRequest(fmt.Sprintf("expected PackageRevision object, got %T", newRuntimeObj))
395396
}
396397

398+
klog.V(3).Infof("PackageRevision update validation completed: %s", name)
399+
400+
if oldApiPkgRev != nil {
401+
action := getLifecycleTransition(oldApiPkgRev.(*porchapi.PackageRevision), newApiPkgRev)
402+
klog.Infof("%s operation started for package revision: %s", action, name)
403+
} else {
404+
klog.Infof("Update operation started for package revision: %s", name)
405+
}
406+
397407
prKey, err := repository.PkgRevK8sName2Key(namespace, name)
398408
if err != nil {
399409
return nil, false, err
@@ -454,7 +464,7 @@ func (r *packageCommon) updatePackageRevision(ctx context.Context, name string,
454464
return updated, false, nil
455465
}
456466

457-
// getUpdateAction determines the type of update operation
467+
// getLifecycleTransition determines the type of lifecycle transition in progress
458468
func getLifecycleTransition(oldPkgRev, newPkgRev *porchapi.PackageRevision) string {
459469
// Handle lifecycle changes
460470
if oldPkgRev.Spec.Lifecycle != newPkgRev.Spec.Lifecycle {

‎pkg/registry/porch/packagerevision.go‎

Lines changed: 13 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,8 @@ func (r *packageRevisions) List(ctx context.Context, options *metainternalversio
7373
ctx, span := tracer.Start(ctx, "[START]::packageRevisions::List", trace.WithAttributes())
7474
defer span.End()
7575

76+
klog.V(3).Infof("List packageRevisions started")
77+
7678
result := &porchapi.PackageRevisionList{
7779
TypeMeta: metav1.TypeMeta{
7880
Kind: "PackageRevisionList",
@@ -96,7 +98,7 @@ func (r *packageRevisions) List(ctx context.Context, options *metainternalversio
9698
return nil, err
9799
}
98100

99-
klog.V(3).Infof("List packagerevisions completed: found %d items", len(result.Items))
101+
klog.V(3).Infof("List packageRevisions completed: found %d items", len(result.Items))
100102

101103
return result, nil
102104
}
@@ -106,6 +108,8 @@ func (r *packageRevisions) Get(ctx context.Context, name string, options *metav1
106108
ctx, span := tracer.Start(ctx, "[START]::packageRevisions::Get", trace.WithAttributes())
107109
defer span.End()
108110

111+
klog.V(3).Infof("Get packageRevisions started: %s", name)
112+
109113
repoPkgRev, err := r.getRepoPkgRev(ctx, name)
110114
if err != nil {
111115
return nil, err
@@ -116,7 +120,7 @@ func (r *packageRevisions) Get(ctx context.Context, name string, options *metav1
116120
return nil, err
117121
}
118122

119-
klog.V(3).Infof("Get packagerevision completed: %s", name)
123+
klog.V(3).Infof("Get packageRevisions completed: %s", name)
120124

121125
return apiPkgRev, nil
122126
}
@@ -149,6 +153,9 @@ func (r *packageRevisions) Create(ctx context.Context, runtimeObject runtime.Obj
149153
return nil, apierrors.NewBadRequest("spec.repositoryName is required")
150154
}
151155

156+
action := createAction(newApiPkgRev)
157+
klog.Infof("%s operation started for packageRevision: %s.%s.%s", action, repositoryName, newApiPkgRev.Spec.PackageName, newApiPkgRev.Spec.WorkspaceName)
158+
152159
repositoryObj, err := r.getRepositoryObj(ctx, types.NamespacedName{Name: repositoryName, Namespace: ns})
153160
if err != nil {
154161
return nil, err
@@ -192,8 +199,7 @@ func (r *packageRevisions) Create(ctx context.Context, runtimeObject runtime.Obj
192199
return nil, apierrors.NewInternalError(err)
193200
}
194201

195-
action := createAction(newApiPkgRev)
196-
klog.Infof("%s operation completed for package revision: %s", action, createdApiPkgRev.Name)
202+
klog.Infof("%s operation completed for packageRevision: %s", action, createdApiPkgRev.Name)
197203

198204
return createdApiPkgRev, nil
199205
}
@@ -273,6 +279,8 @@ func (r *packageRevisions) Delete(ctx context.Context, name string, deleteValida
273279
return nil, false, apierrors.NewBadRequest("namespace must be specified")
274280
}
275281

282+
klog.Infof("Delete operation started for packageRevision: %s", name)
283+
276284
repoPkgRev, err := r.getRepoPkgRev(ctx, name)
277285
if err != nil {
278286
return nil, false, err
@@ -305,7 +313,7 @@ func (r *packageRevisions) Delete(ctx context.Context, name string, deleteValida
305313
return nil, false, apierrors.NewInternalError(err)
306314
}
307315

308-
klog.Infof("Delete operation completed: %s", name)
316+
klog.Infof("Delete operation completed for packageRevision: %s", name)
309317

310318
// TODO: Should we do an async delete?
311319
return apiPkgRev, true, nil

‎pkg/registry/porch/packagerevisionresources.go‎

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,8 @@ func (r *packageRevisionResources) List(ctx context.Context, options *metaintern
7070
ctx, span := tracer.Start(ctx, "[START]::packageRevisionResources::List", trace.WithAttributes())
7171
defer span.End()
7272

73+
klog.V(3).Infoln("List packageRevisionResources started")
74+
7375
result := &porchapi.PackageRevisionResourcesList{
7476
TypeMeta: metav1.TypeMeta{
7577
Kind: "PackageRevisionResourcesList",
@@ -93,7 +95,7 @@ func (r *packageRevisionResources) List(ctx context.Context, options *metaintern
9395
return nil, err
9496
}
9597

96-
klog.V(3).Infof("List packagerevisionresources completed: found %d items", len(result.Items))
98+
klog.V(3).Infof("List packageRevisionResources completed: found %d items", len(result.Items))
9799

98100
return result, nil
99101
}
@@ -103,6 +105,8 @@ func (r *packageRevisionResources) Get(ctx context.Context, name string, options
103105
ctx, span := tracer.Start(ctx, "[START]::packageRevisionResources::Get", trace.WithAttributes())
104106
defer span.End()
105107

108+
klog.V(3).Infof("Get packageRevisionResources started: %s", name)
109+
106110
pkg, err := r.getRepoPkgRev(ctx, name)
107111
if err != nil {
108112
return nil, err
@@ -113,7 +117,7 @@ func (r *packageRevisionResources) Get(ctx context.Context, name string, options
113117
return nil, err
114118
}
115119

116-
klog.V(3).Infof("Get packagerevisionresources completed: %s", name)
120+
klog.V(3).Infof("Get packageRevisionResources completed: %s", name)
117121

118122
return apiPkgResources, nil
119123
}
@@ -130,6 +134,8 @@ func (r *packageRevisionResources) Update(ctx context.Context, name string, objI
130134
return nil, false, apierrors.NewBadRequest("namespace must be specified")
131135
}
132136

137+
klog.Infof("Update operation started for packageRevisionResources: %s", name)
138+
133139
pkgMutexKey := getPackageMutexKey(namespace, name)
134140
pkgMutex := getMutexForPackage(pkgMutexKey)
135141
locked := pkgMutex.TryLock()
@@ -198,7 +204,7 @@ func (r *packageRevisionResources) Update(ctx context.Context, name string, objI
198204
created.Status.RenderStatus = *renderStatus
199205
}
200206

201-
klog.Infof("Update operation completed for packagerevisionresources: %s", name)
207+
klog.Infof("Update operation completed for packageRevisionResources: %s", name)
202208

203209
return created, false, nil
204210
}

0 commit comments

Comments
 (0)