internal/related: add more logging for watcher
Gaby logs show that the cron job is still repeatedly
looking at the same issues (not double-posting, just
seemingly not always advancing its watcher).
Add more logging to hopefully give a hint as to
what is going on.
Change-Id: I6d294656a7d9000cde271dc0c2ca07ff0812930b
Reviewed-on: https://go-review.googlesource.com/c/oscar/+/615140
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
diff --git a/internal/related/related.go b/internal/related/related.go
index bd55d9c..7965752 100644
--- a/internal/related/related.go
+++ b/internal/related/related.go
@@ -153,21 +153,25 @@
// When [Poster.EnablePosts] has not been called, Run only logs the comments it would post.
// Future calls to Run will reprocess the same issues and re-log the same comments.
func (p *Poster) Run(ctx context.Context) error {
- p.slog.Info("related.Poster start", "name", p.name)
- defer p.slog.Info("related.Poster end", "name", p.name)
+ p.slog.Info("related.Poster start", "name", p.name, "post", p.post, "latest", p.watcher.Latest())
+ defer func() {
+ p.slog.Info("related.Poster end", "name", p.name, "latest", p.watcher.Latest())
+ }()
defer p.watcher.Flush()
-
for e := range p.watcher.Recent() {
advance, err := p.postIssue(ctx, e)
if err != nil {
- p.slog.Error("related.Poster", "issue", e.Issue, "error", err)
+ p.slog.Error("related.Poster", "issue", e.Issue, "event", e, "error", err)
continue
}
if advance {
p.watcher.MarkOld(e.DBTime)
// Flush immediately to make sure we don't re-post if interrupted later in the loop.
p.watcher.Flush()
+ p.slog.Info("related.Poster advanced watcher", "latest", p.watcher.Latest(), "event", e)
+ } else {
+ p.slog.Info("related.Poster watcher not advanced", "latest", p.watcher.Latest(), "event", e)
}
}
return nil
@@ -222,7 +226,7 @@
func (p *Poster) postIssue(ctx context.Context, e *github.Event) (advance bool, _ error) {
if skip, reason := p.skip(e); skip {
p.slog.Info("related.Poster skip", "name", p.name, "project",
- e.Project, "issue", e.Issue, "reason", reason)
+ e.Project, "issue", e.Issue, "reason", reason, "event", e)
return false, nil
}
@@ -232,7 +236,7 @@
defer p.db.Unlock(lock)
if p.posted(e) {
- p.slog.Info("related.Poster already posted", "name", p.name, "project", e.Project, "issue", e.Issue)
+ p.slog.Info("related.Poster already posted", "name", p.name, "project", e.Project, "issue", e.Issue, "event", e)
// If posting is enabled, we can advance the watcher because
// a comment has already been posted for this issue.
return p.post, nil
@@ -245,7 +249,7 @@
return false, fmt.Errorf("%w url=%s", errVectorSearchFailed, u)
}
if len(results) == 0 {
- p.slog.Info("related.Poster found no related documents", "name", p.name, "project", e.Project, "issue", e.Issue)
+ p.slog.Info("related.Poster found no related documents", "name", p.name, "project", e.Project, "issue", e.Issue, "event", e)
// If posting is enabled, an issue with no related documents
// should be considered handled, and not looked at again.
return p.post, nil
diff --git a/internal/related/related_test.go b/internal/related/related_test.go
index 788b235..6a37d77 100644
--- a/internal/related/related_test.go
+++ b/internal/related/related_test.go
@@ -140,20 +140,23 @@
check(p.Post(ctx, project, 19))
checkEdits(t, p.github.Testing().Edits(), map[int64]string{19: post19})
+ testutil.ExpectLog(t, buf, "advanced watcher", 0)
p.github.Testing().ClearEdits()
// Post does not advance Run's watcher, so it operates on all issues.
check(p.Run(ctx))
checkEdits(t, p.github.Testing().Edits(), map[int64]string{13: post13})
- testutil.ExpectLog(t, buf, "already posted", 1) // issue 19
+ testutil.ExpectLog(t, buf, "already posted", 1) // issue 19
+ testutil.ExpectLog(t, buf, "advanced watcher", 2) // issue 13 and 19 both advance watcher
p.github.Testing().ClearEdits()
// Run is a no-op because previous call to run advanced watcher past issue 19.
check(p.Run(ctx))
checkEdits(t, p.github.Testing().Edits(), nil)
- testutil.ExpectLog(t, buf, "already posted", 1) // no change
+ testutil.ExpectLog(t, buf, "already posted", 1) // no change
+ testutil.ExpectLog(t, buf, "advanced watcher", 2) // no change
})
t.Run("post-run-async", func(t *testing.T) {
