From 0b684b59e5ef761575830e9bcdfebcb13c6d2132 Mon Sep 17 00:00:00 2001
From: Sean Quah <8349537+squahtx@users.noreply.github.com>
Date: Thu, 28 Apr 2022 16:49:50 +0100
Subject: [PATCH] Fix logging of incorrect status codes for disconnected
 requests (#12580)

The status code of requests must always be set, regardless of client
disconnection, otherwise they will always be logged as 200!.

Broken for `respond_with_json` in
f48792eec43f893f4f893ffdcbf00f8958b6f6b5.
Broken for `respond_with_json_bytes` in
3e58ce72b42f2ae473c1e76a967548cd6fa7e2e6.
Broken for `respond_with_html_bytes` in
ea26e9a98b0541fc886a1cb826a38352b7599dbe.

Signed-off-by: Sean Quah <seanq@element.io>
---
 changelog.d/12580.bugfix    |  1 +
 synapse/http/server.py      | 12 +++++++++---
 tests/handlers/test_cas.py  | 14 +++++++++++++-
 tests/handlers/test_saml.py | 14 +++++++++++++-
 4 files changed, 36 insertions(+), 5 deletions(-)
 create mode 100644 changelog.d/12580.bugfix

diff --git a/changelog.d/12580.bugfix b/changelog.d/12580.bugfix
new file mode 100644
index 000000000..bedce405e
--- /dev/null
+++ b/changelog.d/12580.bugfix
@@ -0,0 +1 @@
+Fix a long standing bug where status codes would almost always get logged as 200!, irrespective of the actual status code, when clients disconnect before a request has finished processing.
diff --git a/synapse/http/server.py b/synapse/http/server.py
index b8a7a0f5d..1cf49830e 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -683,6 +683,9 @@ def respond_with_json(
     Returns:
         twisted.web.server.NOT_DONE_YET if the request is still active.
     """
+    # The response code must always be set, for logging purposes.
+    request.setResponseCode(code)
+
     # could alternatively use request.notifyFinish() and flip a flag when
     # the Deferred fires, but since the flag is RIGHT THERE it seems like
     # a waste.
@@ -697,7 +700,6 @@ def respond_with_json(
     else:
         encoder = _encode_json_bytes
 
-    request.setResponseCode(code)
     request.setHeader(b"Content-Type", b"application/json")
     request.setHeader(b"Cache-Control", b"no-cache, no-store, must-revalidate")
 
@@ -728,13 +730,15 @@ def respond_with_json_bytes(
     Returns:
         twisted.web.server.NOT_DONE_YET if the request is still active.
     """
+    # The response code must always be set, for logging purposes.
+    request.setResponseCode(code)
+
     if request._disconnected:
         logger.warning(
             "Not sending response to request %s, already disconnected.", request
         )
         return None
 
-    request.setResponseCode(code)
     request.setHeader(b"Content-Type", b"application/json")
     request.setHeader(b"Content-Length", b"%d" % (len(json_bytes),))
     request.setHeader(b"Cache-Control", b"no-cache, no-store, must-revalidate")
@@ -840,6 +844,9 @@ def respond_with_html_bytes(request: Request, code: int, html_bytes: bytes) -> N
         code: The HTTP response code.
         html_bytes: The HTML bytes to use as the response body.
     """
+    # The response code must always be set, for logging purposes.
+    request.setResponseCode(code)
+
     # could alternatively use request.notifyFinish() and flip a flag when
     # the Deferred fires, but since the flag is RIGHT THERE it seems like
     # a waste.
@@ -849,7 +856,6 @@ def respond_with_html_bytes(request: Request, code: int, html_bytes: bytes) -> N
         )
         return None
 
-    request.setResponseCode(code)
     request.setHeader(b"Content-Type", b"text/html; charset=utf-8")
     request.setHeader(b"Content-Length", b"%d" % (len(html_bytes),))
 
diff --git a/tests/handlers/test_cas.py b/tests/handlers/test_cas.py
index a54aa29cf..751025c5d 100644
--- a/tests/handlers/test_cas.py
+++ b/tests/handlers/test_cas.py
@@ -201,4 +201,16 @@ class CasHandlerTestCase(HomeserverTestCase):
 
 def _mock_request():
     """Returns a mock which will stand in as a SynapseRequest"""
-    return Mock(spec=["getClientIP", "getHeader", "_disconnected"])
+    mock = Mock(
+        spec=[
+            "finish",
+            "getClientIP",
+            "getHeader",
+            "setHeader",
+            "setResponseCode",
+            "write",
+        ]
+    )
+    # `_disconnected` musn't be another `Mock`, otherwise it will be truthy.
+    mock._disconnected = False
+    return mock
diff --git a/tests/handlers/test_saml.py b/tests/handlers/test_saml.py
index 8d4404eda..e2f0f90ef 100644
--- a/tests/handlers/test_saml.py
+++ b/tests/handlers/test_saml.py
@@ -349,4 +349,16 @@ class SamlHandlerTestCase(HomeserverTestCase):
 
 def _mock_request():
     """Returns a mock which will stand in as a SynapseRequest"""
-    return Mock(spec=["getClientIP", "getHeader", "_disconnected"])
+    mock = Mock(
+        spec=[
+            "finish",
+            "getClientIP",
+            "getHeader",
+            "setHeader",
+            "setResponseCode",
+            "write",
+        ]
+    )
+    # `_disconnected` musn't be another `Mock`, otherwise it will be truthy.
+    mock._disconnected = False
+    return mock