Add debug logs to figure out why an event was filtered

[MadLittleMods]

Spawned while investigating #13944,

Add debug logs to figure out why an event was filtered.

This way we might get some more context whenever an 403 Forbidden - body: {"errcode":"M_FORBIDDEN","error":"You don't have permission to access that event."} error is produced.

Dev notes

log_config.yaml

loggers:
    synapse:
        level: INFO

    synapse.visibility:
        level: DEBUG

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Pull request includes a sign off
• Code style is correct
  (run the linters)

[clokep]

This all looks fairly heavy, would it make sense to use a custom logger, like the issue_8631_logger?

Note that we also tend to guard against doing calculations we won't need:

synapse/synapse/storage/databases/main/devices.py

Lines 295 to 299 in 5f659d4

	if issue_8631_logger.isEnabledFor(logging.DEBUG):
	data = {(user, device): stream_id for user, device, stream_id, _ in updates}
	issue_8631_logger.debug(
	"device updates need to be sent to %s: %s", destination, data
	)

I don't know how important that is here though.

[clokep]

I guess my thought is -- do you see value in leaving these long term?

[MadLittleMods]

The value for me comes from seeing these in tests. Since they're debug that doesn't happen by default which sucks. We could add a custom logger and enable it to show in tests? Seems do-able for Complement tests since we can change the logging config.

It's just nice to be able to look at the CI log and figure out why an event isn't being returned. There are so many places where an event can disappear here and it's nice to know why.

[clokep]

For unit tests we have SYNAPSE_TEST_LOG_LEVEL=DEBUG to see debug logs, sytest doesn't have anything, complement seems to have SYNAPSE_TEST_LOG_LEVEL too?

If we only want these to debug some things, do we need to merge it or just get some CI runs going?

[MadLittleMods]

For unit tests we have SYNAPSE_TEST_LOG_LEVEL=DEBUG to see debug logs, sytest doesn't have anything, complement seems to have SYNAPSE_TEST_LOG_LEVEL too?

I was more talking about the default in CI and if changing the log level locally, having to choose between useful INFO and noisy DEBUG is not great. I'm thinking about having these logs shown by default 🤔. It probably doesn't make sense to have these show at the INFO level for production but I think it would in tests.

I'm also conscious of this being noise itself but I feel like these logs are one of the easy things to eliminate a bunch of possibilities. For example, if I see that a relevant event is an outlier, soft-failed, then that's a good unexpected indicator explaining it. filter_events_for_client is used in /sync, /messages, /context which are all common end-to-end assertion touch points (also notifications, relations).

I'm happy to close this PR if you're not seeing it 🙂 (the idea of it might be better than doing this)

[clokep]

I'll take another look (or someone else from the team can before I'm back)!

[MadLittleMods]

Tackling the follow-up here in #14213

[MadLittleMods]

Thanks for the review @clokep and @erikjohnston 🦗