Bug 2083156 - Report PhabBugz feed lag and pending story gauges to statsd

extensions/PhabBugz/lib/Feed.pm

@@ -12,7 +12,7 @@ use 5.10.1;
 use IO::Async::Timer::Periodic;
 use IO::Async::Loop;
 use IO::Async::Signal;
-use List::Util qw(first);
+use List::Util qw(first max);
 use List::MoreUtils qw(uniq);
 use Moo;
 use Try::Tiny;
@@ -150,6 +150,9 @@ sub feed_query {
   my $new_stories = $self->new_stories($story_last_id);
   INFO("No new stories") unless @$new_stories;
 
+  # Report lag before processing so the gauge keeps rising if a story fails.
+  $self->report_feed_lag($new_stories);
+
   # Process each story
   foreach my $story_data (@$new_stories) {
     my $story_id    = $story_data->{id};
@@ -176,6 +179,25 @@ sub feed_query {
   }
 }
 
+sub report_feed_lag {
+  my ($self, $new_stories) = @_;
+
+  my $lag = feed_lag_seconds($new_stories, time);
+  INFO("FEED_LAG_SECONDS: $lag");
+
+  if (my $dd = Bugzilla->datadog) {
+    $dd->gauge('bugzilla.phabbugz.feed_lag_seconds',     $lag);
+    $dd->gauge('bugzilla.phabbugz.feed_pending_stories', scalar @$new_stories);
+  }
+}
+
+# Return the age in seconds of the oldest unprocessed story, or 0 when caught up.
+sub feed_lag_seconds {
+  my ($new_stories, $now) = @_;
+  return 0 unless @$new_stories && $new_stories->[0]{epoch};
+  return max(0, $now - $new_stories->[0]{epoch});
+}
+
 sub user_query {
   my ($self) = @_;
 

extensions/PhabBugz/t/feed-daemon-guts.t

@@ -130,6 +130,64 @@ foreach my $bad_response (@bad_response) {
   $UserAgent->reset('post');
 }
 
+# `feed_lag_seconds` reports the age of the oldest unprocessed story.
+{
+  my $now = 1_000_000;
+
+  is(Bugzilla::Extension::PhabBugz::Feed::feed_lag_seconds([], $now),
+    0, '`feed_lag_seconds` is 0 when there are no new stories.');
+
+  is(
+    Bugzilla::Extension::PhabBugz::Feed::feed_lag_seconds(
+      [{id => 1, epoch => $now - 600}, {id => 2, epoch => $now - 60}], $now
+    ),
+    600,
+    '`feed_lag_seconds` uses the epoch of the oldest story.'
+  );
+
+  is(
+    Bugzilla::Extension::PhabBugz::Feed::feed_lag_seconds(
+      [{id => 1, epoch => $now + 30}], $now
+    ),
+    0,
+    '`feed_lag_seconds` does not go negative when clocks are skewed.'
+  );
+}
+
+# `feed_query` sends lag gauges before processing, even if a story fails.
+{
+  my %gauges;
+  my $datadog = mock {} => (
+    add => [
+      gauge     => sub { my ($self, $name, $value) = @_; $gauges{$name} = $value },
+      increment => sub { },
+    ]
+  );
+  my $Bugzilla = mock 'Bugzilla' => (override => [datadog => sub {$datadog}]);
+
+  my $oldest_epoch = time - 900;
+  my $Feed         = mock 'Bugzilla::Extension::PhabBugz::Feed' => (
+    override => [
+      get_last_id => sub {5},
+      new_stories => sub { [
+        {id => 6, epoch => $oldest_epoch,     text => 'story 6'},
+        {id => 7, epoch => $oldest_epoch + 1, text => 'story 7'},
+      ] },
+      _process_feed_story => sub { die "poison story\n" },
+    ]
+  );
+
+  my $error;
+  try { Bugzilla::Extension::PhabBugz::Feed->new->feed_query }
+  catch { $error = $_ };
+
+  is($error, "poison story\n", '`feed_query` propagates the story failure.');
+  cmp_ok($gauges{'bugzilla.phabbugz.feed_lag_seconds'},
+    '>=', 900, '`feed_lag_seconds` gauge is sent before the failing story.');
+  is($gauges{'bugzilla.phabbugz.feed_pending_stories'},
+    2, '`feed_pending_stories` gauge counts the fetched stories.');
+}
+
 my $feed = Bugzilla::Extension::PhabBugz::Feed->new;
 my $json = JSON::MaybeXS->new(canonical => 1, pretty => 1);
 my $dylan