if you try to do SAS in response to a KS req within a few seconds it takes ~30s for the SAS req to propagate

[ara4n]

it looks like you have to wait for the next /sync to return to receive the toDevice messages. however, if you wait 5-10s before responding to the KS req it's all fiiiiiiine

[ara4n]

(or if you do something on the receiving client to trigger it to /sync (e.g. send a typing notif or a presence req) then the req arrives instantly.

[turt2live]

I wonder how much of this is a Synapse issue...

[turt2live]

@ara4n I can't reproduce this. Are you still seeing it?

(and have we eliminated matrix.org just being slow?)

[turt2live]

Presuming this is because of matrix.org being slow as it hasn't been complained about recently.

[ara4n]

I just caught this red handed (and have hit it intermittently on a fairly regular basis). The ready message got delayed somewhere for 14 seconds.

The device that sent it was:

03:29:10.110 rageshake.js?16c9:65 PUT /sendToDevice/m.key.verification.ready/m1615174150110.0 {@matthewtest7:matrix.org: Array(1)}@matthewtest7:matrix.org: ["LGFPVHDGHM"]__proto__: Object
03:29:10.180 rageshake.js?16c9:65 Verification request 5gzwBW7HDa7gIaerMgERdg48qOI5Ccam: m.key.verification.ready event with id:undefined, content:{"methods":["m.sas.v1","m.qr_code.show.v1","m.reciprocate.v1"],"transaction_id":"5gzwBW7HDa7gIaerMgERdg48qOI5Ccam","from_device":"LFHMXZJBXB"} deviceId:LGFPVHDGHM, sender:@matthewtest7:matrix.org, isSentByUs:true, isLiveEvent:true, isRemoteEcho:true, phase:2=>3, observeOnly:false=>false

The device that received it was:

03:29:24.147 rageshake.js?16c9:65 received to_device m.key.verification.ready from: @matthewtest7:matrix.org id: undefined
03:29:24.151 rageshake.js?16c9:65 Verification request 5gzwBW7HDa7gIaerMgERdg48qOI5Ccam: m.key.verification.ready event with id:undefined, content:{"methods":["m.sas.v1","m.qr_code.show.v1","m.reciprocate.v1"],"transaction_id":"5gzwBW7HDa7gIaerMgERdg48qOI5Ccam","from_device":"LFHMXZJBXB"} deviceId:LFHMXZJBXB, sender:@matthewtest7:matrix.org, isSentByUs:false, isLiveEvent:true, isRemoteEcho:false, phase:2=>3, observeOnly:false=>false

Need to spelunk in synapse's logs for that particular request to see where the delay came from.

[ara4n]

Spelunking in synapse, we see:

2021-03-08 03:29:10,184 - synapse.access.http.8134 - 329 - INFO - PUT-5209281 - 92.233.2.138 - 8134 - {@matthewtest7:matrix.org} Processed request: 0.008sec/-0.000sec (0.004sec, 0.000sec) (0.001sec/0.003sec/3) 2B 200
 "PUT /_matrix/client/r0/sendToDevice/m.key.verification.ready/m1615174150110.0 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.192 Safari/537.36" [0
 dbevts]
2021-03-08 03:29:10,187 - synapse.replication.tcp.resource - 189 - INFO - replication_notifier-3065984 - Streaming: to_device -> 223870325

in the encryption worker... and then:

2021-03-08 03:29:03,104 - synapse.access.http.8086 - 329 - INFO - GET-10063351 - 92.233.2.138 - 8086 - {@matthewtest7:matrix.org} Processed request: 7.000sec/-0.000sec (0.004sec, 0.000sec) (0.001sec/0.004sec/2) 691B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s1862136738_757284961_10407083_771873329_645114725_2124766_223870309_798409877_177132 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.192 Safari/537.36" [0 dbevts]
2021-03-08 03:29:24,026 - synapse.access.http.8086 - 329 - INFO - GET-10063893 - 92.233.2.138 - 8086 - {@matthewtest7:matrix.org} Processed request: 0.603sec/-0.000sec (0.008sec, 0.000sec) (0.031sec/0.042sec/2) 663B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s1862136868_757284961_10407259_771873413_645114828_2124766_223870318_798409879_177132 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.192 Safari/537.36" [0 dbevts]
2021-03-08 03:29:33,176 - synapse.access.http.8086 - 329 - INFO - GET-10063508 - 92.233.2.138 - 8086 - {@matthewtest7:matrix.org} Processed request: 30.003sec/-0.000sec (0.004sec, 0.002sec) (0.003sec/0.005sec/4) 439B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s1862136868_757284961_10407259_771873413_645114828_2124766_223870318_798409879_177132 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.192 Safari/537.36" [0 dbevts]
2021-03-08 03:29:54,223 - synapse.access.http.8086 - 329 - INFO - GET-10063896 - 92.233.2.138 - 8086 - {@matthewtest7:matrix.org} Processed request: 30.003sec/-0.000sec (0.003sec, 0.001sec) (0.002sec/0.004sec/3) 439B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s1862137249_757284961_10407814_771873627_645115137_2124766_223870344_798409884_177132 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.192 Safari/537.36" [0 dbevts]

...in the sync worker. So it looks like synapse only decided to wake up the sync worker after 14s, which seems dubiously long.
There are no gaps in the logs indicating a GC on either worker.

[ara4n]

(meanwhile synapse as a whole is pretty quiet right now).

@callahad do we have jaeger available to chase this down? random toDevice delays of up to 30s have been occurring since we landed SAS at FOSDEM 2019...