A guide to the request log lines format.

[michaelkaye]

Sharing notes on the meaning of the request log lines (specifically how to decode all the timings in brackets) - i always have to go read the source to find this out.

[richvdh]

I'll point you to https://github.com/matrix-org/synapse/wiki#what-do-all-those-fields-in-the-processed-line-mean, though arguably it should be easier to find

[michaelkaye]

Cheers for the link; if we want to move this into the wiki because it's not suitable for docs I'm happy to copy-pasta (I'll admit i can't quite grok the format without the comparison section) I'm happy with that too; but we should definitely have some sort of link from the /docs folder or the README to the wiki if that's part of the documentation.

[clokep]

I suspect this makes more sense in our docs folder since we don't really have anything else on the wiki?

[richvdh]

agreed.

[erikjohnston]

@michaelkaye can you add a note where we log to say that if its updated to remember to update the docs please?

synapse/synapse/http/site.py

Lines 310 to 314 in c9d981f

	self.site.access_logger.log(
	log_level,
	"%s - %s - {%s}"
	" Processed request: %.3fsec/%.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)"
	' %sB %s "%s %s %s" "%s" [%d dbevts]',

[richvdh]

if the intention is that this replaces the wiki doc, it would be good to cover some other points here. Examples:

• this applies specifically to lines matching Processed request from synapse.access.http.* loggers.
• The "send response" time (JJJJ) may be negative if the client goes away before we finish processing.
• The response code (QQQQ) will have a ! suffix if the client dropped the connection before we sent the response.
• the db times may be higher than total time, due to parallelism
• This is only correct if you use the default log format - if you configure your logging differently, it may look a bit different

[erikjohnston]

(I made these comments ages ago, and then forgot to press submit...)

[michaelkaye]

* the db times may be higher than total time, due to parallelism

I couldn't express this in a single sentence; why is parallelism a thing and where did the time go?

[erikjohnston]

This seems sensible to me, but would like @richvdh to have a look

For legibility it might also be good to convert all the "AAA" etc in the table/text to be AAA, I find the III especially weird to read, compared with III, but that might just be me

[richvdh]

I'm afraid I'm going to close this, since nobody seems to have time to push it over the line.

[daenney]

Pushed fixes for the review comments.

[richvdh]

thanks @daenney !

[richvdh]

lgtm now.

It would be good to include this in the new docs site, which AIUI mostly requires adding a link to SUMMARY.md. Also, we should maybe put it in the docs/administration directory? @anoadragon453 can you check if there is anything else needed here?

[anoadragon453]

Sorry for the long round-trip time. Putting it in docs/usage/administration sounds good to me. In SUMMARY.md it looks like it'd probably fit best below the Admin API section, alongside "Manhole" and "Monitoring".

There shouldn't be anything else to do other than that 🙂