Further reduce INFO logging

[erikjohnston]

Some candidates that could be removed from default logging:

1. OPTIONS request processing (~7% of log lines on jki.re)
2. /sync request processing (~7% of log lines on jki.re, ignoring INFO)
3. Sending request (~12% of log lines on jki.re)
4. Received txn from (~11% of log lines on jki.re), though we probably(?) want to somehow log how many PDUs the transaction contained in the processing request log line (or maybe have a generic "how many new events were persitsed" like we do for dbevts)

[erikjohnston]

Is roughly what is happening over a day for jki.re

[erikjohnston]

Note that debian have changed the default log level for some particular handlers: https://salsa.debian.org/matrix-team/matrix-synapse/-/blob/debian/unstable/debian/log.yaml

[clokep]

Sending device list update notif for ... tends to end up with very long log lines (at least on matrix.org).

[erikjohnston]

We now do a lot of log lines around:

2022-04-27 09:34:08,508 - synapse.replication.tcp.handler - 593 - INFO - process-replication-data-23576884 - Caught up with stream 'events' to 2893728403
2022-04-27 09:34:08,509 - synapse.replication.tcp.handler - 540 - INFO - replication_command_handler-140374159398168 - Handling 'POSITION events event_persister-2 2893728399 2893728400'

which are probably not needed at INFO

[erikjohnston]

We should take another crack at this, otherwise we may need to reduce log retention to uncomfortable levels on matrix.org.

[H-Shay]

Totally dumb question but for my own edification:
I've noticed that whenever anything goes wrong/behaves mysteriously in Synapse usually the first order of business is to add log lines. I am wondering then why we are removing them here (presumably whoever added them to begin with thought they might be of some use) rather than doing something like only storing a minimal number of days of logs (like 5?) on the servers they were generated on and then moving the older logs to some sort of backup storage where they can be maintained for 14-21 days or whatever people feel comfortable with. I am imaging this is something that could be automated-just wondering why we wouldn't do this.

[erikjohnston]

Good question Shay! Some notes:

• Yes we do want to have an off-box log archive, but that is something that is non-trivial and is on the Ops backlog
• We automatically delete old logs, but without a log archive we don't really want to go too low.
• There are other deployments out there, which would also benefit from this work.

I've noticed that whenever anything goes wrong/behaves mysteriously in Synapse usually the first order of business is to add log lines.

This is true, but the flip side is that we often fail to remove the logging when we've tracked down the issues. It's quite easy to slowly accrue extra log lines over time, so it is worth going through and periodically seeing if there is anything that can be pruned.

[erikjohnston]

#12610 seems to have helped reduce our log sizes by 25-50%