events get soft-failed when the federation_inbound worker is busy

[richvdh]

event ids $44J0EFE_wD30pBA2EZ2hu_viEDWZ55CFZCJEliLoQOY, $d6_JvuU1AdlqnwBEK2shSB30_qFWIiZPlg526HJJuQQ, $FnodZIXcp1YSMx1RTvfp1RZIp51VgU32JCQaVmEv8Z8 were all mysteriously soft-failed on matrix.org, presumably because synapse thought that the sender wasn't in the room - but she had joined a clear 3 minutes earlier.

[richvdh]

inspection of the state_groups around that event show clearly that the sender of the event was in the room. It's not even a particularly complex DAG, so it kinda has to be a transient problem with "current_state". Possibly there was a delay in invalidating the current_state cache on the worker processing the inbound events?

next steps might be to dig up the logs for when those events arrived over federation to see if there is anything funky?

[erikjohnston]

FWIW I think we keep track of the forward extremities at a given stream position in stream_ordering_to_exterm table

[richvdh]

so we have, on the master:

2020-06-24 18:27:40,673 - synapse.replication.http.membership - 230 - INFO - POST-7968707 - user membership change: @<user> in !<room>

and then, on federation_inbound:

2020-06-24 18:30:10,443 - synapse.handlers.federation - 2125 - WARNING - PUT-6586266-$44J0EFE_wD30pBA2EZ2hu_viEDWZ55CFZCJEliLoQOY - Soft-failing <FrozenEventV3 event_id='$44J0EFE_wD30pBA2EZ2hu_viEDWZ55CFZCJEliLoQOY', type='m.room.message', state_key='None'> because 403: User @<user> not in room !<room> (<FrozenEventV3 event_id='$_nUedokc9-SqfRglu-uUwmCTN6lhXgT2lFhjUXwUFug', type='m.room.member', state_key='@<user>'>)

so indeed it looks like a cache isn't being correctly flushed.

[richvdh]

so, the federation inbound worker was 250K events behind at the time:

This is an ongoing problem.

[richvdh]

see also: #7444

[richvdh]

also see also: #7669

[richvdh]

also also see also: #6536 -> #10066