Add some light labels to the Processed request logs (#19548)

It's pretty hard to remember the order of all of these ambiguous
numbers. I assume they're not totally labeled already to cut down on the
length when scanning with your eyes. This just adds a few hints of what
each grouping is.

Spawning from [staring at some Synapse
logs](element-hq/matrix-hosted#10631) and
cross-referencing the Synapse source code over and over.

Author: MadLittleMods

changelog.d/19548.misc

@@ -0,0 +1 @@
+Add a few labels to the number groupings in the `Processed request` logs.

docs/upgrade.md

@@ -146,6 +146,14 @@ No immediate change is necessary, however once the parameter is removed, modules
 From this version, when the parameter is passed, an error such as
 ``Deprecated `deactivation` parameter passed to `set_displayname` Module API (value: False). This will break in 2027.`` will be logged. The method will otherwise continue to work.
 
+## Updated request log format (`Processed request: ...`)
+
+The [request log format](usage/administration/request_log.md) has slightly changed to
+include `ru=(...)` and `db=(...)` labels to better disambiguate the number groupings.
+Previously, these values appeared without labels.
+
+This only matters if you have third-party tooling that parses the Synapse logs.
+
 # Upgrading to v1.146.0
 
 ## Drop support for Ubuntu 25.04 Plucky Puffin, and add support for 25.10 Questing Quokka

docs/usage/administration/request_log.md

@@ -5,8 +5,8 @@ HTTP request logs are written by synapse (see [`synapse/http/site.py`](https://g
 See the following for how to decode the dense data available from the default logging configuration.
 
 ```
-2020-10-01 12:00:00,000 - synapse.access.http.8008 - 311 - INFO - PUT-1000- 192.168.0.1 - 8008 - {another-matrix-server.com} Processed request: 0.100sec/-0.000sec (0.000sec, 0.000sec) (0.001sec/0.090sec/3) 11B !200 "PUT /_matrix/federation/v1/send/1600000000000 HTTP/1.1" "Synapse/1.20.1" [0 dbevts]
--AAAAAAAAAAAAAAAAAAAAA-   -BBBBBBBBBBBBBBBBBBBBBB-   -C-   -DD-   -EEEEEE-  -FFFFFFFFF-   -GG-    -HHHHHHHHHHHHHHHHHHHHHHH-                     -IIIIII- -JJJJJJJ-  -KKKKKK-, -LLLLLL-  -MMMMMMM- -NNNNNN- O  -P- -QQ-  -RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR-   -SSSSSSSSSSSS-   -TTTTTT-
+2020-10-01 12:00:00,000 - synapse.access.http.8008 - 311 - INFO - PUT-1000- 192.168.0.1 - 8008 - {another-matrix-server.com} Processed request: 0.100sec/-0.000sec ru=(0.000sec, 0.000sec) db=(0.001sec/0.090sec/3) 11B !200 "PUT /_matrix/federation/v1/send/1600000000000 HTTP/1.1" "Synapse/1.20.1" [0 dbevts]
+-AAAAAAAAAAAAAAAAAAAAA-   -BBBBBBBBBBBBBBBBBBBBBB-   -C-   -DD-   -EEEEEE-  -FFFFFFFFF-   -GG-    -HHHHHHHHHHHHHHHHHHHHHHH-                     -IIIIII- -JJJJJJJ-     -KKKKKK-, -LLLLLL-      -MMMMMM- -NNNNNN- O  -P- -QQ-  -RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR-   -SSSSSSSSSSSS-   -TTTTTT-
 ```
 
 

synapse/http/site.py

@@ -638,10 +638,12 @@ def _finished_processing(self) -> None:
         if authenticated_entity:
             requester = f"{authenticated_entity}|{requester}"
 
+        # Updates to this log line should also be reflected in our docs,
+        # `docs/usage/administration/request_log.md`
         self.synapse_site.access_logger.log(
             log_level,
             "%s - %s - {%s}"
-            " Processed request: %.3fsec/%.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)"
+            " Processed request: %.3fsec/%.3fsec ru=(%.3fsec, %.3fsec) db=(%.3fsec/%.3fsec/%d)"
             ' %sB %s "%s %s %s" "%s" [%d dbevts]',
             self.get_client_ip_if_available(),
             self.synapse_site.site_tag,