From f7f92db755a207625198e0e486c9ac3f7833bcb8 Mon Sep 17 00:00:00 2001 From: Michael Kaye <1917473+michaelkaye@users.noreply.github.com> Date: Thu, 1 Oct 2020 13:25:35 +0100 Subject: [PATCH 01/10] This doc is short but a useful guide to what the request log lines mean. --- docs/request_log.md | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) create mode 100644 docs/request_log.md diff --git a/docs/request_log.md b/docs/request_log.md new file mode 100644 index 000000000000..3dc47b6a89a0 --- /dev/null +++ b/docs/request_log.md @@ -0,0 +1,34 @@ +# Request log format + +HTTP request logs are written by synapse (see synapse/http/site.py for details. + +See the following for how to decode the dense data available here. + +``` +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- -Q- -RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR- -SSSSSSSSSSSS- -TTTTTT- +``` + + +| Part | Explaination | +| ----- | ------------ | +| AAAA | Timestamp request was logged (not recieved) | +| BBBB | Logger name (usually the same as the python class ) | +| CCCC | Line number in code | +| DDDD | Log Level | +| EEEE | Request Identifier (This identifier is shared by related log lines)| +| FFFF | Source IP (Or X-Forwarded-For if enabled) | +| GGGG | Server Port | +| HHHH | Federated Server or Local User making request (blank if unauthenticated or not supplied) | +| IIII | Total Time to process | +| JJJJ | Time to send response over network once generated | +| KKKK | Userland time | +| LLLL | System time | +| MMMM | Total time waiting for DB connections | +| NNNN | Total time waiting for response to DB queries | +| OOOO | Count of DB transactions performed | +| PPPP | Response body size | +| QQQQ | Response status code | +| RRRR | Request | +| SSSS | User-agent | +| TTTT | Events fetched from DB to service this request | From 222252c22b8537052c7c5f9967aeab43c1b1c358 Mon Sep 17 00:00:00 2001 From: Michael Kaye <1917473+michaelkaye@users.noreply.github.com> Date: Thu, 1 Oct 2020 13:37:05 +0100 Subject: [PATCH 02/10] Add changelog --- changelog.d/8436.doc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/8436.doc diff --git a/changelog.d/8436.doc b/changelog.d/8436.doc new file mode 100644 index 000000000000..77fc09820008 --- /dev/null +++ b/changelog.d/8436.doc @@ -0,0 +1 @@ +Add a new guide to decoding request logs. From 7ef104c19c722f6f4eb28fc603c18a7fbe7a4378 Mon Sep 17 00:00:00 2001 From: Michael Kaye <1917473+michaelkaye@users.noreply.github.com> Date: Mon, 1 Mar 2021 11:10:39 +0000 Subject: [PATCH 03/10] Apply suggestions from code review Co-authored-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Co-authored-by: Erik Johnston --- docs/request_log.md | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/docs/request_log.md b/docs/request_log.md index 3dc47b6a89a0..5d6107c76f3a 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -1,6 +1,6 @@ # Request log format -HTTP request logs are written by synapse (see synapse/http/site.py for details. +HTTP request logs are written by synapse (see [`site.py`](../synapse/http/site.py) for details). See the following for how to decode the dense data available here. @@ -22,13 +22,13 @@ See the following for how to decode the dense data available here. | HHHH | Federated Server or Local User making request (blank if unauthenticated or not supplied) | | IIII | Total Time to process | | JJJJ | Time to send response over network once generated | -| KKKK | Userland time | -| LLLL | System time | -| MMMM | Total time waiting for DB connections | +| KKKK | Userland CPU time | +| LLLL | System CPU time | +| MMMM | Total time waiting for a free DB connection from the pool | | NNNN | Total time waiting for response to DB queries | | OOOO | Count of DB transactions performed | | PPPP | Response body size | | QQQQ | Response status code | | RRRR | Request | | SSSS | User-agent | -| TTTT | Events fetched from DB to service this request | +| TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) | From b41f7e733261ff628d61eac51fa80f6178c2e616 Mon Sep 17 00:00:00 2001 From: Michael Kaye <1917473+michaelkaye@users.noreply.github.com> Date: Mon, 1 Mar 2021 11:14:10 +0000 Subject: [PATCH 04/10] Update request_log.md --- docs/request_log.md | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/docs/request_log.md b/docs/request_log.md index 5d6107c76f3a..a66b1f429b3b 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -5,22 +5,22 @@ HTTP request logs are written by synapse (see [`site.py`](../synapse/http/site.p See the following for how to decode the dense data available here. ``` -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- -Q- -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 (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- ``` | Part | Explaination | | ----- | ------------ | | AAAA | Timestamp request was logged (not recieved) | -| BBBB | Logger name (usually the same as the python class ) | +| BBBB | Logger name (synapse.access.(http|https)., where 'tag' is defined in the `listeners` config section, normally the port) | | CCCC | Line number in code | | DDDD | Log Level | | EEEE | Request Identifier (This identifier is shared by related log lines)| | FFFF | Source IP (Or X-Forwarded-For if enabled) | | GGGG | Server Port | | HHHH | Federated Server or Local User making request (blank if unauthenticated or not supplied) | -| IIII | Total Time to process | +| IIII | Total Time to process (prefixed with - if the socket was closed before the response was generated) | | JJJJ | Time to send response over network once generated | | KKKK | Userland CPU time | | LLLL | System CPU time | @@ -28,7 +28,7 @@ See the following for how to decode the dense data available here. | NNNN | Total time waiting for response to DB queries | | OOOO | Count of DB transactions performed | | PPPP | Response body size | -| QQQQ | Response status code | +| QQQQ | Response status code (prefixed with ! if the socket was closed before the response was generated) | | RRRR | Request | | SSSS | User-agent | | TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) | From 43e63b2e2f456eb48b9864bbff1e74910cbe1297 Mon Sep 17 00:00:00 2001 From: Michael Kaye <1917473+michaelkaye@users.noreply.github.com> Date: Mon, 1 Mar 2021 11:16:02 +0000 Subject: [PATCH 05/10] Update request_log.md --- docs/request_log.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/request_log.md b/docs/request_log.md index a66b1f429b3b..c913d8f412c7 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -2,7 +2,7 @@ HTTP request logs are written by synapse (see [`site.py`](../synapse/http/site.py) for details). -See the following for how to decode the dense data available here. +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] From 5accfb8f1b86133865f6238a7c5d9fdb64fa4be1 Mon Sep 17 00:00:00 2001 From: Michael Kaye <1917473+michaelkaye@users.noreply.github.com> Date: Mon, 1 Mar 2021 11:51:01 +0000 Subject: [PATCH 06/10] Update request_log.md --- docs/request_log.md | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/docs/request_log.md b/docs/request_log.md index c913d8f412c7..d07f2f27648c 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -24,11 +24,17 @@ See the following for how to decode the dense data available from the default lo | JJJJ | Time to send response over network once generated | | KKKK | Userland CPU time | | LLLL | System CPU time | -| MMMM | Total time waiting for a free DB connection from the pool | -| NNNN | Total time waiting for response to DB queries | +| MMMM | Total time waiting for a free DB connection from the pool across all parallel DB work from this request | +| NNNN | Total time waiting for response to DB queries across all parallel DB work from this request | | OOOO | Count of DB transactions performed | | PPPP | Response body size | | QQQQ | Response status code (prefixed with ! if the socket was closed before the response was generated) | | RRRR | Request | | SSSS | User-agent | | TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) | + + +MMMM / NNNN can be greater than IIII if there are multiple slow database queries running in parallel. + +Some actions can result in multiple identical http requests, which will return the same data, but only the first request will report any time in IIII/NNNN/MMMM - the others will be awaiting the first query to return a response and will simultaneously return with the first request, but with very small processing times. + From c3e37d9da44f56b72ad861897c587af0cce6ec3e Mon Sep 17 00:00:00 2001 From: Daniele Sluijters Date: Wed, 2 Jun 2021 16:40:15 +0200 Subject: [PATCH 07/10] Address review comments --- docs/request_log.md | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/docs/request_log.md b/docs/request_log.md index d07f2f27648c..276740a917a2 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -13,15 +13,15 @@ See the following for how to decode the dense data available from the default lo | Part | Explaination | | ----- | ------------ | | AAAA | Timestamp request was logged (not recieved) | -| BBBB | Logger name (synapse.access.(http|https)., where 'tag' is defined in the `listeners` config section, normally the port) | +| BBBB | Logger name (synapse.access.(http\|https)., where 'tag' is defined in the `listeners` config section, normally the port) | | CCCC | Line number in code | | DDDD | Log Level | | EEEE | Request Identifier (This identifier is shared by related log lines)| | FFFF | Source IP (Or X-Forwarded-For if enabled) | | GGGG | Server Port | | HHHH | Federated Server or Local User making request (blank if unauthenticated or not supplied) | -| IIII | Total Time to process (prefixed with - if the socket was closed before the response was generated) | -| JJJJ | Time to send response over network once generated | +| IIII | Total Time to process the request | +| JJJJ | Time to send response over network once generated (this may be negative if the socket is closed before the response is generated)| | KKKK | Userland CPU time | | LLLL | System CPU time | | MMMM | Total time waiting for a free DB connection from the pool across all parallel DB work from this request | @@ -34,7 +34,11 @@ See the following for how to decode the dense data available from the default lo | TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) | -MMMM / NNNN can be greater than IIII if there are multiple slow database queries running in parallel. - -Some actions can result in multiple identical http requests, which will return the same data, but only the first request will report any time in IIII/NNNN/MMMM - the others will be awaiting the first query to return a response and will simultaneously return with the first request, but with very small processing times. +MMMM / NNNN can be greater than IIII if there are multiple slow database queries +running in parallel. +Some actions can result in multiple identical http requests, which will return +the same data, but only the first request will report any time in +`IIII/NNNN/MMMM` - the others will be awaiting the first query to return a +response and will simultaneously return with the first request, but with very +small processing times. From 1dca7e1fdab190335dcbe2d8dd83faf371b7c0df Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Fri, 4 Jun 2021 09:45:59 +0100 Subject: [PATCH 08/10] Update request_log.md --- docs/request_log.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/request_log.md b/docs/request_log.md index 276740a917a2..dc2aef4c341e 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -13,7 +13,7 @@ See the following for how to decode the dense data available from the default lo | Part | Explaination | | ----- | ------------ | | AAAA | Timestamp request was logged (not recieved) | -| BBBB | Logger name (synapse.access.(http\|https)., where 'tag' is defined in the `listeners` config section, normally the port) | +| BBBB | Logger name (`synapse.access.(http\|https).`, where 'tag' is defined in the `listeners` config section, normally the port) | | CCCC | Line number in code | | DDDD | Log Level | | EEEE | Request Identifier (This identifier is shared by related log lines)| From f334da4ddaf68e416f57e043a6176132e2694ec7 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Fri, 4 Jun 2021 09:54:01 +0100 Subject: [PATCH 09/10] Apply suggestions from code review --- docs/request_log.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/docs/request_log.md b/docs/request_log.md index dc2aef4c341e..316304c7348a 100644 --- a/docs/request_log.md +++ b/docs/request_log.md @@ -10,7 +10,7 @@ See the following for how to decode the dense data available from the default lo ``` -| Part | Explaination | +| Part | Explanation | | ----- | ------------ | | AAAA | Timestamp request was logged (not recieved) | | BBBB | Logger name (`synapse.access.(http\|https).`, where 'tag' is defined in the `listeners` config section, normally the port) | @@ -38,7 +38,7 @@ MMMM / NNNN can be greater than IIII if there are multiple slow database queries running in parallel. Some actions can result in multiple identical http requests, which will return -the same data, but only the first request will report any time in -`IIII/NNNN/MMMM` - the others will be awaiting the first query to return a +the same data, but only the first request will report time/transactions in +`KKKK`/`LLLL`/`MMMM`/`NNNN`/`OOOO` - the others will be awaiting the first query to return a response and will simultaneously return with the first request, but with very small processing times. From f1e7d2638d9719fa7ecdb90d2aaf146cdebfa0fb Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 16 Jun 2021 13:03:19 +0100 Subject: [PATCH 10/10] Add to new docs site --- docs/SUMMARY.md | 1 + docs/{ => usage/administration}/request_log.md | 0 2 files changed, 1 insertion(+) rename docs/{ => usage/administration}/request_log.md (100%) diff --git a/docs/SUMMARY.md b/docs/SUMMARY.md index af2c968c9abe..01ef4ff600af 100644 --- a/docs/SUMMARY.md +++ b/docs/SUMMARY.md @@ -61,6 +61,7 @@ - [Server Version](admin_api/version_api.md) - [Manhole](manhole.md) - [Monitoring](metrics-howto.md) + - [Request log format](usage/administration/request_log.md) - [Scripts]() # Development diff --git a/docs/request_log.md b/docs/usage/administration/request_log.md similarity index 100% rename from docs/request_log.md rename to docs/usage/administration/request_log.md