From 1d143074c5534912cf40d28a4c31deabab2b1710 Mon Sep 17 00:00:00 2001
From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com>
Date: Thu, 3 Jun 2021 16:01:30 +0100
Subject: [PATCH] Improve opentracing annotations for Notifier (#10111)

The existing tracing reports an error each time there is a timeout, which isn't
really representative.

Additionally, we log things about the way `wait_for_events` works
(eg, the result of the callback) to the *parent* span, which is confusing.
---
 changelog.d/10111.misc |  1 +
 synapse/notifier.py    | 64 +++++++++++++++++++++---------------------
 2 files changed, 33 insertions(+), 32 deletions(-)
 create mode 100644 changelog.d/10111.misc

diff --git a/changelog.d/10111.misc b/changelog.d/10111.misc
new file mode 100644
index 000000000..42e42b69a
--- /dev/null
+++ b/changelog.d/10111.misc
@@ -0,0 +1 @@
+Improve opentracing annotations for `Notifier`.
diff --git a/synapse/notifier.py b/synapse/notifier.py
index 24b4e6649..3c3cc4763 100644
--- a/synapse/notifier.py
+++ b/synapse/notifier.py
@@ -485,21 +485,21 @@ class Notifier:
             end_time = self.clock.time_msec() + timeout
 
             while not result:
-                try:
-                    now = self.clock.time_msec()
-                    if end_time <= now:
-                        break
+                with start_active_span("wait_for_events"):
+                    try:
+                        now = self.clock.time_msec()
+                        if end_time <= now:
+                            break
 
-                    # Now we wait for the _NotifierUserStream to be told there
-                    # is a new token.
-                    listener = user_stream.new_listener(prev_token)
-                    listener.deferred = timeout_deferred(
-                        listener.deferred,
-                        (end_time - now) / 1000.0,
-                        self.hs.get_reactor(),
-                    )
+                        # Now we wait for the _NotifierUserStream to be told there
+                        # is a new token.
+                        listener = user_stream.new_listener(prev_token)
+                        listener.deferred = timeout_deferred(
+                            listener.deferred,
+                            (end_time - now) / 1000.0,
+                            self.hs.get_reactor(),
+                        )
 
-                    with start_active_span("wait_for_events.deferred"):
                         log_kv(
                             {
                                 "wait_for_events": "sleep",
@@ -517,27 +517,27 @@ class Notifier:
                             }
                         )
 
-                    current_token = user_stream.current_token
+                        current_token = user_stream.current_token
 
-                    result = await callback(prev_token, current_token)
-                    log_kv(
-                        {
-                            "wait_for_events": "result",
-                            "result": bool(result),
-                        }
-                    )
-                    if result:
+                        result = await callback(prev_token, current_token)
+                        log_kv(
+                            {
+                                "wait_for_events": "result",
+                                "result": bool(result),
+                            }
+                        )
+                        if result:
+                            break
+
+                        # Update the prev_token to the current_token since nothing
+                        # has happened between the old prev_token and the current_token
+                        prev_token = current_token
+                    except defer.TimeoutError:
+                        log_kv({"wait_for_events": "timeout"})
+                        break
+                    except defer.CancelledError:
+                        log_kv({"wait_for_events": "cancelled"})
                         break
-
-                    # Update the prev_token to the current_token since nothing
-                    # has happened between the old prev_token and the current_token
-                    prev_token = current_token
-                except defer.TimeoutError:
-                    log_kv({"wait_for_events": "timeout"})
-                    break
-                except defer.CancelledError:
-                    log_kv({"wait_for_events": "cancelled"})
-                    break
 
         if result is None:
             # This happened if there was no timeout or if the timeout had