Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Clean up some logging #6515

Merged
merged 1 commit into from Dec 11, 2019
Merged

Clean up some logging #6515

merged 1 commit into from Dec 11, 2019

Conversation

@richvdh
Copy link
Member

richvdh commented Dec 10, 2019

This just makes some of the logging easier to follow when things start
going wrong.

This just makes some of the logging easier to follow when things start going
wrong.
@richvdh richvdh force-pushed the rav/event_auth/12 branch from 88d3644 to c97fee0 Dec 10, 2019
@richvdh richvdh requested a review from matrix-org/synapse-core Dec 10, 2019
@@ -182,7 +182,7 @@ def on_receive_pdu(self, origin, pdu, sent_to_us_directly=False):
room_id = pdu.room_id
event_id = pdu.event_id

logger.info("[%s %s] handling received PDU: %s", room_id, event_id, pdu)

This comment has been minimized.

Copy link
@erikjohnston

erikjohnston Dec 11, 2019

Member

Why remove the prefixing? I find it quite useful to track how we're processing an event?

This comment has been minimized.

Copy link
@richvdh

richvdh Dec 11, 2019

Author Member

because it's in the logcontext anyway.

This comment has been minimized.

Copy link
@erikjohnston

erikjohnston Dec 11, 2019

Member

Oh, so it is. I had forgotten the log context isn't the generic request one. Carry on.

raise Exception(
"Error fetching missing prev_events for %s: %s"
% (event_id, e)
)

This comment has been minimized.

Copy link
@erikjohnston

erikjohnston Dec 11, 2019

Member

I'd be tempted to not include e and rely on the exception chaining (raise Exception(..) from e).

(I assume we've checked that get_missing_events_for_pdu doesn't raise any expected exceptions.)

This comment has been minimized.

Copy link
@richvdh

richvdh Dec 11, 2019

Author Member

I'd be tempted to not include e and rely on the exception chaining (raise Exception(..) from e).

I tried that. It made for remarkably unreadable errors, not least because the exception chain is epic.

Exception chaining happens by default when you raise an exception from an except block, afaik

This comment has been minimized.

Copy link
@richvdh

richvdh Dec 11, 2019

Author Member

(I assume we've checked that get_missing_events_for_pdu doesn't raise any expected exceptions.)

well: first, I've looked at the places on_receive_pdu is called (ie, the places that might care that we turn one sort of exception into a generic Exception). There are two such places: _handle_queued_pdus, in which all exceptions are treated equally, and get_missing_events_for_pdu (again), which does treat FederationError with code=403 specially.

Then going down through get_missing_events_for_pdu, the only things which might raise a FederationError are federation_client.get_missing_events (which I'm 99% sure doesn't), and on_receive_pdu which, as discussed, filters out such exceptions. So I'm reasonably confident it's not possible for get_missing_events_for_pdu to raise a FederationError with code=403, and therefore this change shouldn't make any difference.

Copy link
Member

erikjohnston left a comment

Up to you about using raise .. from ..

@richvdh richvdh merged commit 7c429f9 into develop Dec 11, 2019
22 checks passed
22 checks passed
buildkite/synapse Build #6066 passed (21 minutes, 13 seconds)
Details
buildkite/synapse/check-sample-config Passed (1 minute, 36 seconds)
Details
buildkite/synapse/check-style Passed (2 minutes, 11 seconds)
Details
buildkite/synapse/isort Passed (16 seconds)
Details
buildkite/synapse/mypy Passed (22 seconds)
Details
buildkite/synapse/newspaper-newsfile Passed (14 seconds)
Details
buildkite/synapse/packaging Passed (22 seconds)
Details
buildkite/synapse/pipeline Passed (3 seconds)
Details
buildkite/synapse/python-3-dot-5-slash-postgres-9-dot-5 Passed (18 minutes, 25 seconds)
Details
buildkite/synapse/python-3-dot-5-slash-sqlite Passed (7 minutes, 42 seconds)
Details
buildkite/synapse/python-3-dot-5-slash-sqlite-slash-old-deps Passed (8 minutes, 8 seconds)
Details
buildkite/synapse/python-3-dot-6-slash-sqlite Passed (6 minutes, 47 seconds)
Details
buildkite/synapse/python-3-dot-7-slash-postgres-11 Passed (18 minutes, 43 seconds)
Details
buildkite/synapse/python-3-dot-7-slash-postgres-9-dot-5 Passed (18 minutes, 38 seconds)
Details
buildkite/synapse/python-3-dot-7-slash-sqlite Passed (7 minutes, 12 seconds)
Details
buildkite/synapse/synapse-port-db-slash-python-3-dot-5-slash-postgres-9-dot-5 Passed (1 minute, 56 seconds)
Details
buildkite/synapse/synapse-port-db-slash-python-3-dot-7-slash-postgres-11 Passed (1 minute, 15 seconds)
Details
buildkite/synapse/sytest-python-3-dot-5-slash-postgres-9-dot-6-slash-monolith Passed (12 minutes, 6 seconds)
Details
buildkite/synapse/sytest-python-3-dot-5-slash-postgres-9-dot-6-slash-workers Passed (14 minutes, 47 seconds)
Details
buildkite/synapse/sytest-python-3-dot-5-slash-sqlite-slash-monolith Passed (12 minutes, 25 seconds)
Details
buildkite/synapse/sytest-python-3-dot-7-slash-postgres-11-slash-monolith Passed (10 minutes, 33 seconds)
Details
buildkite/synapse/sytest-python-3-dot-7-slash-postgres-11-slash-workers Passed (12 minutes, 4 seconds)
Details
@richvdh richvdh deleted the rav/event_auth/12 branch Dec 11, 2019
@richvdh

This comment has been minimized.

Copy link
Member Author

richvdh commented Dec 11, 2019

oh, another thing that's worth noting about relying on the exception chaining:

the exception message here actually ends up getting sent back to the sending server. So for example:

{
  "pdus": {
    "$gTbOW9yxHJ9SkILmPz42b5t_NpN2XnD5Dk_SO_7cCBM": {
      "error": "Error fetching missing prev_events for $gTbOW9yxHJ9SkILmPz42b5t_NpN2XnD5Dk_SO_7cCBM: 404: Could not find event $-xeoZouRJKbRQ_MoNe5hff5gzaumxzIwcfscKgAtQy8"
    }
  }
}

There are other bugs that mean that error is completely bogus ($-xeo actually failed auth, rather than being missing), but it's progress in the right direction imho

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.