-
-
Notifications
You must be signed in to change notification settings - Fork 2.1k
Add debug logs to figure out why an event was filtered #14095
Add debug logs to figure out why an event was filtered #14095
Conversation
To have less noise, maybe we only want to log when an event is filtered out and not why it was returned unscathed. See #14095 (comment)
ad5a023
to
b73713f
Compare
synapse/visibility.py
Outdated
if len(events_before_filtering) != len(events): | ||
logger.debug( | ||
"filter_events_for_client: Filtered out soft-failed events: Before=%s, After=%s", | ||
[event.event_id for event in events_before_filtering], | ||
[event.event_id for event in events], | ||
) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I guess my thought is -- do you see value in leaving these long term?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'll take another look (or someone else from the team can before I'm back)!
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Tackling the follow-up here in #14213
Thanks for the review @clokep and @erikjohnston 🦗 |
…#14213) See #14095 (comment) This is useful because when see that a relevant event is an `outlier` or `soft-failed`, then that's a good unexpected indicator explaining why it's not showing up. `filter_events_for_client` is used in `/sync`, `/messages`, `/context` which are all common end-to-end assertion touch points (also notifications, relations).
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
Pull Request Checklist
EventStore
toEventWorkerStore
.".code blocks
.Pull request includes a sign off(run the linters)