Accepting invites on matrix.org is no longer reliable.

[ara4n]

At least on my account and Amandine's, it seems that it's very easy for something to go wrong with Synapse since ~November which means the client believes the accept has failed; either a timeout or an exception. You are then stuck in limbo unless you flush the cache, as per:

element-hq/element-ios#2153

Someone needs to hunt whatever happened with the logs on those rageshakes.

[ara4n]

(i've also seen lots of other anecdotal evidence of this happening over the last ~month, and have to keep telling people to flush their cache).

[richvdh]

I wouldn't be entirely surprised to discover this is related to some of the unfinished lazy-loading work, fwiw.

[richvdh]

An instance of this from matthew on 1 Feb:

2019-02-01 23:36:13,013 - synapse.handlers.sync - 1402 - INFO - GET-3120426 - Membership changes in <room_id>: [$1549064172149644GTXRt:matrix.org (join)]
2019-02-01 23:36:13,333 - synapse.storage.roommember - 94 - INFO - GET-3120426 - Fetched room membership for ! <room_id> (2 users) in 9 ms
2019-02-01 23:36:13,341 - synapse.access.http.8098 - 302 - INFO - GET-3120426 - 194.78.14.74 - 8098 - {@matthew:matrix.org} Processed request: 2.950sec/0.001sec (0.076sec, 0.004sec) (0.009sec/0.266sec/11) 432B 200 "GET /_matri/client/r0/sync?etc"

Another on 14 Feb:

2019-02-14 11:34:48,750 - synapse.access.http.8098 - 233 - INFO - GET-6199846 - 80.250.101.234 - 8098 - Received request: GET /_matrix/client/r0/sync?filter=139&set_presence=offline&since=s840348390_754815119_586165_237988328_113322494_596735_18432257_11836808_31828&timeout=0
2019-02-14 11:34:48,751 - synapse.util.caches.response_cache - 151 - INFO - GET-6199846 - [sync]: no cached result for [(@matthew:matrix.org, 0, 's840348390_754815119_586165_237988328_113322494_596735_18432257_11836808_31828', '139', False, 'NBHCUILQXV')], calculating new one
2019-02-14 11:34:48,751 - synapse.handlers.sync - 909 - INFO - GET-6199846 - Calculating sync response for @matthew:matrix.org between StreamToken(room_key='s840348390', presence_key='754815119', typing_key='586165', receipt_key='237988328', account_data_key='113322494', push_rules_key='596735', to_device_key='18432257', device_list_key='11836808', groups_key='31828') and StreamToken(room_key='s840349675', presence_key=754817859, typing_key=586790, receipt_key=237988945, account_data_key=113322868, push_rules_key=596735, to_device_key=18432300, device_list_key=11836831, groups_key=31828)
2019-02-14 11:34:48,772 - synapse.handlers.sync - 1402 - INFO - GET-6199846 - Membership changes in !<room_id>: [$1550143986277856SDgkf:matrix.org (join)]
2019-02-14 11:34:49,919 - synapse.access.http.8098 - 302 - INFO - GET-6199846 - 80.250.101.234 - 8098 - {@matthew:matrix.org} Processed request: 1.167sec/0.002sec (0.100sec, 0.000sec) (0.057sec/0.247sec/21) 17582B 200 "GET /_matrix/client/r0/sync?filter=139&set_presence=offline&since=s840348390_754815119_586165_237988328_113322494_596735_18432257_11836808_31828&timeout=0 HTTP/1.1" "Riot/0.7.11 (iPhone; iOS 12.1.2; Scale/3.00)" [6 dbevts]

[richvdh]

I've added some more debugging for this to matrix.org, so please let me know when you see it again

[richvdh]

so I managed to reproduce an instance of this, and got some debug out of it:

2019-03-12 12:23:40,449 - synapse.handlers.sync - 912 - INFO - GET-15459791 - Calculating sync response for @richvdh:matrix.org between StreamToken(room_key='s872000229', presence_key='757242052', typing_key='832786', receipt_key='254199105', account_data_key='125873516', push_rules_key='643156', to_device_key='20082070', device_list_key='12533569', groups_key=
2019-03-12 12:23:40,480 - synapse.handlers.sync - 1414 - INFO - GET-15459791 - Membership changes in !dSodagOCcZCEPOhgZW:sw1v.org: [$1552393420415287uTeoF:matrix.org (join)]
2019-03-12 12:23:40,493 - synapse.handler.sync.4422_debug - 1451 - DEBUG - GET-15459791 - Previous membership for room !dSodagOCcZCEPOhgZW:sw1v.org with join: invite (event $1552393414489avAHM:sw1v.org)
2019-03-12 12:23:40,521 - synapse.storage.roommember - 94 - INFO - GET-15459791 - Fetched room membership for !dSodagOCcZCEPOhgZW:sw1v.org (3 users) in 2 ms
2019-03-12 12:23:40,530 - synapse.access.http.8088 - 302 - INFO - GET-15459791 - 2001:8b0:ba7a:e98f:3252:cbff:fee8:6489 - 8088 - {@richvdh:matrix.org} Processed request: 2.563sec/0.000sec (0.012sec, 0.004sec) (0.015sec/0.043sec/12) 453B 200 "GET /_matrix/client/r0/sync?filter=148&timeout=30000&since=s872000229_757242052_832786_254199105_125873516_643156_2008207

The "previous membership..." line comes from here and the fact that it is not then followed by a bunch of debug about newly joined rooms from here implies that the new room has not made it into sync_result_builder.joined_room_ids despite the join having landed with stream id 872000269.

joined_room_ids is built here. So presumably get_rooms_for_user_with_stream_ordering (which has a cache) returned a stale result, though I'm unsure how this happened.

[richvdh]

get_rooms_for_user_with_stream_ordering's cache should have been invalidated by this entry in the cache invalidation stream:

matrix=# select * from cache_invalidation_stream where stream_id=558594235;
 stream_id |  cache_func   |                        keys                        | invalidation_ts 
-----------+---------------+----------------------------------------------------+-----------------
 558594235 | cs_cache_fake | {!dSodagOCcZCEPOhgZW:sw1v.org,@richvdh:matrix.org} |   1552393420347

(invalidation_ts is 12:23:40.347).

However, this wasn't sent out by the master until 12:23:40.450:

2019-03-12 12:23:40,450 - synapse.replication.tcp.resource - 181 - INFO - replication_notifier-2492793 - Streaming: caches -> 558594235

The join event (stream id 872000269) was sent out at 12:23:40.426:

2019-03-12 12:23:40,426 - synapse.replication.tcp.resource - 181 - INFO - replication_notifier-2492793 - Streaming: events -> 872000271

It's therefore clear that there is a window where the worker can see the new join event (because its event stream id has been updated to include it), but has not yet received the cache invalidation.

The replication notifier makes no particular effort to preserve the ordering of events and caches notifications, so this isn't entirely surprising. I'm not really sure how best to fix it, though.

[richvdh]

hopefully fixed by #4956; please let me know if you see more instances of it.

[richvdh]

[Probably worth mentioning that #4533 is still a thing].