From 9a0888aacd51cc94992ea509221e94d6b1d4f369 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?P=C4=93teris=20Caune?= <cuu508@gmail.com>
Date: Fri, 15 Jan 2021 15:15:00 +0200
Subject: [PATCH] Update sendalerts to log per-notification send times

To send notifications, sendalerts calls Flip.send_alerts().
I updated Flip.send_alerts() to be a generator, and to yield
a (channel, error, send_time_in_seconds) triple per sent
notification.
---
 hc/api/management/commands/sendalerts.py | 17 +++++---
 hc/api/models.py                         | 21 ++++++---
 hc/api/tests/test_flip_model.py          | 55 ++++++++++++++++++++++++
 3 files changed, 81 insertions(+), 12 deletions(-)
 create mode 100644 hc/api/tests/test_flip_model.py

diff --git a/hc/api/management/commands/sendalerts.py b/hc/api/management/commands/sendalerts.py
index 62d09506..54a9818c 100644
--- a/hc/api/management/commands/sendalerts.py
+++ b/hc/api/management/commands/sendalerts.py
@@ -29,14 +29,19 @@ def notify(flip_id, stdout):
 
     # Send notifications
     send_start = timezone.now()
-    errors = flip.send_alerts()
-    for ch, error in errors:
-        stdout.write("ERROR: %s %s %s\n" % (ch.kind, ch.value, error))
 
-    # If sending took more than 5s, log it
+    for ch, error, secs in flip.send_alerts():
+        label = "OK"
+        if error:
+            label = "ERROR"
+        elif secs > 5:
+            label = "SLOW"
+
+        s = " * %-5s %4.1fs %-10s %s %s\n" % (label, secs, ch.kind, ch.code, error)
+        stdout.write(s)
+
     send_time = timezone.now() - send_start
-    if send_time.total_seconds() > 5:
-        stdout.write(SEND_TIME_TMPL % (send_time.total_seconds(), check.code))
+    stdout.write(SEND_TIME_TMPL % (send_time.total_seconds(), check.code))
 
     statsd.timing("hc.sendalerts.dwellTime", send_start - flip.created)
     statsd.timing("hc.sendalerts.sendTime", send_time)
diff --git a/hc/api/models.py b/hc/api/models.py
index 4561ce60..8d7ea80a 100644
--- a/hc/api/models.py
+++ b/hc/api/models.py
@@ -2,6 +2,7 @@
 
 import hashlib
 import json
+import time
 import uuid
 from datetime import datetime, timedelta as td
 
@@ -822,20 +823,28 @@ class Flip(models.Model):
         }
 
     def send_alerts(self):
+        """Loop over the enabled channels, call notify() on each.
+
+        For each channel, yield a (channel, error, send_time) triple:
+         * channel is a Channel instance
+         * error is an empty string ("") on success, error message otherwise
+         * send_time is the send time in seconds (float)
+        """
+
+        # Don't send alerts on new->up and paused->up transitions
         if self.new_status == "up" and self.old_status in ("new", "paused"):
-            # Don't send alerts on new->up and paused->up transitions
-            return []
+            return
 
         if self.new_status not in ("up", "down"):
             raise NotImplementedError("Unexpected status: %s" % self.status)
 
-        errors = []
         for channel in self.owner.channel_set.all():
+            start = time.time()
             error = channel.notify(self.owner)
-            if error not in ("", "no-op"):
-                errors.append((channel, error))
+            if error == "no-op":
+                continue
 
-        return errors
+            yield (channel, error, time.time() - start)
 
 
 class TokenBucket(models.Model):
diff --git a/hc/api/tests/test_flip_model.py b/hc/api/tests/test_flip_model.py
new file mode 100644
index 00000000..af78a53a
--- /dev/null
+++ b/hc/api/tests/test_flip_model.py
@@ -0,0 +1,55 @@
+from unittest.mock import patch
+
+from django.utils.timezone import now
+from hc.api.models import Channel, Check, Flip
+from hc.test import BaseTestCase
+
+
+class FlipModelTestCase(BaseTestCase):
+    def setUp(self):
+        super().setUp()
+        self.check = Check.objects.create(project=self.project)
+        self.channel = Channel.objects.create(project=self.project, kind="email")
+        self.channel.checks.add(self.check)
+
+        self.flip = Flip(owner=self.check)
+        self.flip.created = now()
+        self.flip.old_status = "up"
+        self.flip.new_status = "down"
+
+    @patch("hc.api.models.Channel.notify")
+    def test_send_alerts_works(self, mock_notify):
+        mock_notify.return_value = ""
+
+        results = list(self.flip.send_alerts())
+        self.assertEqual(len(results), 1)
+
+        ch, error, send_time = results[0]
+        self.assertEqual(ch, self.channel)
+        self.assertEqual(error, "")
+
+    @patch("hc.api.models.Channel.notify")
+    def test_send_alerts_handles_error(self, mock_notify):
+        mock_notify.return_value = "something went wrong"
+
+        results = list(self.flip.send_alerts())
+        self.assertEqual(len(results), 1)
+
+        ch, error, send_time = results[0]
+        self.assertEqual(error, "something went wrong")
+
+    @patch("hc.api.models.Channel.notify")
+    def test_send_alerts_handles_noop(self, mock_notify):
+
+        mock_notify.return_value = "no-op"
+
+        results = list(self.flip.send_alerts())
+        self.assertEqual(results, [])
+
+    @patch("hc.api.models.Channel.notify")
+    def test_send_alerts_handles_new_up_transition(self, mock_notify):
+        self.flip.old_status = "new"
+        self.flip.new_status = "up"
+
+        results = list(self.flip.send_alerts())
+        self.assertEqual(results, [])