diff options
| author | Michael Kaye <1917473+michaelkaye@users.noreply.github.com> | 2021-06-16 13:31:55 +0100 |
|---|---|---|
| committer | GitHub <noreply@github.com> | 2021-06-16 13:31:55 +0100 |
| commit | b8b282aa32063d712e276373b6bc90c39cecc353 (patch) | |
| tree | 0074dd9ab5140eef621bbb89de150f248cb85b95 /docs/usage/administration | |
| parent | Add debug logging when we enter/exit Measure block (#10183) (diff) | |
| download | synapse-b8b282aa32063d712e276373b6bc90c39cecc353.tar.xz | |
A guide to the request log lines format. (#8436)
This doc is short but a useful guide to what the request log lines mean. Co-authored-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Co-authored-by: Erik Johnston <erik@matrix.org> Co-authored-by: Daniele Sluijters <daenney@users.noreply.github.com>
Diffstat (limited to 'docs/usage/administration')
| -rw-r--r-- | docs/usage/administration/request_log.md | 44 |
1 files changed, 44 insertions, 0 deletions
diff --git a/docs/usage/administration/request_log.md b/docs/usage/administration/request_log.md new file mode 100644 index 0000000000..316304c734 --- /dev/null +++ b/docs/usage/administration/request_log.md @@ -0,0 +1,44 @@ +# Request log format + +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 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- +``` + + +| Part | Explanation | +| ----- | ------------ | +| AAAA | Timestamp request was logged (not recieved) | +| BBBB | Logger name (`synapse.access.(http\|https).<tag>`, 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 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 | +| 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 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. |