From 8ad7e8af81bd655deb2014a7df04cf218c8a829d Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 17 Mar 2026 09:43:05 -0500 Subject: [PATCH] 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](https://github.com/element-hq/matrix-hosted/issues/10631) and cross-referencing the Synapse source code over and over. --- changelog.d/19548.misc | 1 + docs/upgrade.md | 8 ++++++++ docs/usage/administration/request_log.md | 4 ++-- synapse/http/site.py | 4 +++- 4 files changed, 14 insertions(+), 3 deletions(-) create mode 100644 changelog.d/19548.misc diff --git a/changelog.d/19548.misc b/changelog.d/19548.misc new file mode 100644 index 0000000000..eed4d5d8e2 --- /dev/null +++ b/changelog.d/19548.misc @@ -0,0 +1 @@ +Add a few labels to the number groupings in the `Processed request` logs. diff --git a/docs/upgrade.md b/docs/upgrade.md index 777e57c492..aeae82c114 100644 --- a/docs/upgrade.md +++ b/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 diff --git a/docs/usage/administration/request_log.md b/docs/usage/administration/request_log.md index 6154108934..7e3047eb62 100644 --- a/docs/usage/administration/request_log.md +++ b/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- ``` diff --git a/synapse/http/site.py b/synapse/http/site.py index 6ced5b98b3..9b7fd5c936 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -638,10 +638,12 @@ class SynapseRequest(Request): 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,