maxmustermann/synapse
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

A guide to the request log lines format. (#8436)

Browse source 
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>
This commit is contained in:
Michael Kaye 2021-06-16 13:31:55 +01:00 committed by GitHub
parent 36c426e294
commit b8b282aa32
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
3 changed files with 46 additions and 0 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
changelog.d/8436.doc Normal file
View file

@ -0,0 +1 @@
Add a new guide to decoding request logs.

1
docs/SUMMARY.md
View file

@ -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

44
docs/usage/administration/request_log.md Normal file
View file

@ -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.