Stop getting missing prev_events after we already know their signature is invalid

[MadLittleMods]

Stop getting missing prev_events after we already know their signature is invalid. While #13635 stops us from doing the slow thing after we've already done it once, this PR stops us from doing one of the slow things in the first place.

Related to

• Only try to backfill event if we haven't tried before recently #13622
  • Only try to backfill event if we haven't tried before recently (exponential backoff) #13635
• We keep trying to fetch events whose keys have expired or have been invalidated #13676

Part of #13356

Follow-up to #13815 which tracks event signature failures.

With this PR, we avoid the call to the costly _get_state_ids_after_missing_prev_event because the signature failure will count as an attempt before and we filter events based on the backoff before calling _get_state_ids_after_missing_prev_event now.

For example, this will save us 156s out of the 185s total that this matrix.org /messages request. If you want to see the full Jaeger trace of this, you can drag and drop this trace.json into your own Jaeger, https://gist.github.com/MadLittleMods/4b12d0d0afe88c2f65ffcc907306b761

To explain this exact scenario around /messages -> backfill, we call /backfill and first check the signatures of the 100 events. We see bad signature for $luA4l7QHhf_jadH3mI-AyFqho0U2Q-IXXUbGSMq6h6M and $zuOn2Rd2vsC7SUia3Hp3r6JSkSFKcc5j3QTTqW_0jDw (both member events). Then we process the 98 events remaining that have valid signatures but one of the events references $luA4l7QHhf_jadH3mI-AyFqho0U2Q-IXXUbGSMq6h6M as a prev_event. So we have to do the whole _get_state_ids_after_missing_prev_event rigmarole which pulls in those same events which fail again because the signatures are still invalid.

• backfill
  • outgoing-federation-request /backfill
  • _check_sigs_and_hash_and_fetch
    • _check_sigs_and_hash_and_fetch_one for each event received over backfill
      • ❗ $luA4l7QHhf_jadH3mI-AyFqho0U2Q-IXXUbGSMq6h6M fails with Signature on retrieved event was invalid.: unable to verify signature for sender domain xxx: 401: Failed to find any key to satisfy: _FetchKeyRequest(...)
      • ❗ $zuOn2Rd2vsC7SUia3Hp3r6JSkSFKcc5j3QTTqW_0jDw fails with Signature on retrieved event was invalid.: unable to verify signature for sender domain xxx: 401: Failed to find any key to satisfy: _FetchKeyRequest(...)
  • _process_pulled_events
    • _process_pulled_event for each validated event
      • ❗ Event $Q0iMdqtz3IJYfZQU2Xk2WjB5NDF8Gg8cFSYYyKQgKJ0 references $luA4l7QHhf_jadH3mI-AyFqho0U2Q-IXXUbGSMq6h6M as a prev_event which is missing so we try to get it
        • _get_state_ids_after_missing_prev_event
          • outgoing-federation-request /state_ids
          • ❗ get_pdu for $luA4l7QHhf_jadH3mI-AyFqho0U2Q-IXXUbGSMq6h6M which fails the signature check again
          • ❗ get_pdu for $zuOn2Rd2vsC7SUia3Hp3r6JSkSFKcc5j3QTTqW_0jDw which fails the signature check

Dev notes

SYNAPSE_POSTGRES=1 SYNAPSE_TEST_LOG_LEVEL=INFO python -m twisted.trial tests.handlers.test_federation_event.FederationEventHandlerTests.test_backfill_signature_failure_does_not_fetch_same_prev_event_later

Sytest:

source /Users/eric/Documents/github/element/synapse/.venv/bin/activate
./run-tests.pl --synapse-directory ../synapse tests/48admin.pl

docker run --rm -it -v ~/Documents/github/element/synapse:/src:ro -v ~/Documents/github/element/synapse/logs:/logs -v ~/Documents/github/element/sytest:/sytest:ro matrixdotorg/sytest-synapse:buster tests/48admin.pl

docker run --rm -it -e POSTGRES=1 -e WORKERS=1 \
    -v ~/Documents/github/element/synapse:/src:ro \
    -v ~/Documents/github/element/synapse/logs:/logs \
    -v ~/Documents/github/element/sytest:/sytest:ro matrixdotorg/sytest-synapse:buster tests/48admin.pl

Dump all events in the room with useful debug info

Adapted from matrix-org/matrix-react-sdk#8354 for txn (originally from #12370)

logger.info(
    "asdf_get_debug_events_in_room_ordered_by_depth\n%s",
    self.asdf_get_debug_events_in_room_ordered_by_depth_txn(txn, room_id),
)

asdf_get_debug_events_in_room_ordered_by_depth_txn

    def asdf_get_debug_events_in_room_ordered_by_depth_txn(
        self, txn: LoggingTransaction, room_id: str
    ) -> Any:
        """
        Output all events in the room in a nice table as a string to log

        Based on https://github.com/matrix-org/matrix-react-sdk/pull/8354
        """
        sql = (
            "SELECT depth, stream_ordering, type, state_key, outlier, event_id FROM events"
            " WHERE events.room_id = ?"
            " ORDER BY depth DESC, stream_ordering DESC;"
        )
        txn.execute(
            sql,
            (room_id,),
        )

        headerColumnLengthMap = {
            "depth": 4,
            "stream_ordering": 12,
            "type": 30,
            "state_key": 40,
            "outlier": 4,
            # event_ids are 44 long but we don't need the extra 5 padding
            # because it's the last item and we're just cheating by building
            # this into the value instead of the format code.
            "event_id": 39,
        }

        output = ""
        row_format = "".join(
            [
                "{:<" + str(columnLength + 5) + "}"
                for columnLength in headerColumnLengthMap.values()
            ]
        )
        output += row_format.format(*headerColumnLengthMap.keys()) + "\n"
        for row in txn:
            output += row_format.format(*[str(x) for x in row]) + "\n"
        return output

Todo

• Wait for Track when the pulled event signature fails #13815 to merge
• Add tests

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)

[erikjohnston]

It occurs to me that these inline SQL comments get sent over the wire to postgres, which is probably not totally ideal. Might be worth moving the big ones out?

[erikjohnston]

Also, TBH I'm wondering whether for this it would be clearer to just fetch event_id, last_attempt_ts, num_attempts and do the checks in python?

[MadLittleMods]

Also, TBH I'm wondering whether for this it would be clearer to just fetch event_id, last_attempt_ts, num_attempts and do the checks in python?

I think this makes a lot of sense here since we have to get a response out for each event_ids anyway 👍

---

It occurs to me that these inline SQL comments get sent over the wire to postgres, which is probably not totally ideal. Might be worth moving the big ones out?

In terms of other places to worry about this: we already strip out the newlines which is why I use /* */ instead of inline --. Is there a way we can strip the comments out so we don't lose the nice readability? The performance of find/replacing this every time doesn't sound great but our _make_sql_one_line doesn't look particularly optimized by eye either 🤔. I'm not sure why we started doing that (introduced in #1939), maybe to get rid of all of the extra indentation spaces in multi-line strings.

[erikjohnston]

Yeah, I was thinking about that too, though we'd want to make sure that we do it safely (I'm not sure if just stripping /* ... */ is safe by itself).

Note that we don't actually send the one-line SQL to the database, we use it for logging.

[MadLittleMods]

Created #14192 to continue this comments in SQL conversation ⏩

Note that we don't actually send the one-line SQL to the database, we use it for logging.

huh, I swore this was a problem before. Good to know!

[erikjohnston]

I'm not sure it makes sense for this to inherit from SynapseError. The risk is that this manages to bubble all the way to the client API, returning a 403, which seems entirely wrong.

[MadLittleMods]

Makes sense 👍. The docstrings for SynapseError and FederationError could use some improving (would do in separate PR so we don't hang up on that).

We probably want to also update FederationDeniedError in a separate PR as well?

synapse/synapse/api/errors.py

Line 251 in e6e876b

class FederationDeniedError(SynapseError):

[MadLittleMods]

Created #14190 and #14191 to track these follow-up updates to explain those error classes better ⏩

[MadLittleMods]

^ Sanity check appreciated here to make sure we're doing the equivalent of

synapse/synapse/storage/databases/main/event_federation.py

Lines 842 to 857 in b6baa46

	/**
	* Exponential back-off (up to the upper bound) so we don't retry the
	* same backfill point over and over. ex. 2hr, 4hr, 8hr, 16hr, etc.
	*
	* We use `1 << n` as a power of 2 equivalent for compatibility
	* with older SQLites. The left shift equivalent only works with
	* powers of 2 because left shift is a binary operation (base-2).
	* Otherwise, we would use `power(2, n)` or the power operator, `2^n`.
	*/
	AND (
	failed_backfill_attempt_info.event_id IS NULL
	OR ? /* current_time */ >= failed_backfill_attempt_info.last_attempt_ts + (
	(1 << {least_function}(failed_backfill_attempt_info.num_attempts, ? /* max doubling steps */))
	* ? /* step */
	)
	)

[MadLittleMods]

Thanks for the review @erikjohnston 🐫