Complement can_paginate_after_getting_remote_event_from_timestamp_to_event_endpoint is flakey(?)

[DMRobertson]

https://github.com/matrix-org/synapse/actions/runs/3149623842/jobs/5121449357#step:5:5805

❌ TestJumpToDateEndpoint (14.08s)
❌ TestJumpToDateEndpoint/parallel (4.03s)
❌ TestJumpToDateEndpoint/parallel/federation (0s)
❌ TestJumpToDateEndpoint/parallel/federation/can_paginate_after_getting_remote_event_from_timestamp_to_event_endpoint (1.54s)
      msc3030_test.go:195: SendEventSynced waiting for event ID $aEEhbyDijeJ586WpiJCNmpxF41yCQ5Sw0Hd2-0HkpRw
      msc3030_test.go:195: SendEventSynced waiting for event ID $NP6-oU7mIFVyhtKfGvfrEQX949hQX-T-gvuauG6eurU
      msc3030_test.go:200: CSAPI.MustDoFunc response return non-2xx code: 403 Forbidden - body: {"errcode":"M_FORBIDDEN","error":"You don't have permission to access that event."}

Not sure if this is related to @MadLittleMods' work?

[MadLittleMods]

It looks like this might be related to #13444 given we're seeing this log line Unexpectedly did not have cached prev group for $NP6-oU7mIFVyhtKfGvfrEQX949hQX-T-gvuauG6eurU for the event that /context is failing to get.

2022-09-29T08:23:25.7520090Z     client.go:604: [CSAPI] GET hs2/_matrix/client/r0/rooms/!EhRVzzPYBOfRplzGyM:hs1/context/$NP6-oU7mIFVyhtKfGvfrEQX949hQX-T-gvuauG6eurU => 403 Forbidden (26.804412ms)

2022-09-29T08:23:25.7599143Z synapse_main | 2022-09-29 08:21:08,284 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-3 - Unexpectedly did not have cached prev group for $aEEhbyDijeJ586WpiJCNmpxF41yCQ5Sw0Hd2-0HkpRw
2022-09-29T08:23:25.7605062Z synapse_main | 2022-09-29 08:21:08,363 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-4 - Unexpectedly did not have cached prev group for $NP6-oU7mIFVyhtKfGvfrEQX949hQX-T-gvuauG6eurU

Maybe a red herring since not sure that would cause an actual failure though.

---

It is interesting that this reproduced in monolith mode though 🤔

[MadLittleMods]

Sleuthing the server logs on the CI failure, it looks like hs2:/timestamp_to_event found $NP6-oU7mIFVyhtKfGvfrEQX949hQX-T-gvuauG6eurU as an outlier event locally. Then when we went and asked for it via /context, since it's an outlier, it was filtered out of the results -> You don't have permission to access that event.

This is reproducible when sync_partial_state races and persists $NP6-oU7mIFVyhtKfGvfrEQX949hQX-T-gvuauG6eurU as an outlier before we evaluate get_event_for_timestamp(...). To consistently reproduce locally, just add a delay at the start of get_event_for_timestamp(...) so it always runs after sync_partial_state completes.

# TODO: Make sure to assign `self.hs = hs` above
from twisted.internet import task as twisted_task
# wait 3.5s (without blocking anything)
d = twisted_task.deferLater(self.hs.get_reactor(), 3.5)
await d

In a run where it passes, on hs2, get_event_for_timestamp(...) finds a different event locally which is next to a gap and we request from a closer one from hs1 which gets backfilled. And since the backfilled event is not an outlier, it's returned as expected during /context.

---

In get_event_for_timestamp(...), it looks like we also need to backfill the locally found event if it's an outlier.

And/or it would be nice if /context would just backfill the event for us. This would also help with #3848