synchrotron sometimes returns stale presence

[richvdh]

Sometimes the "Newly created users see their own presence in /initialSync" test (https://github.com/matrix-org/sytest/blob/develop/tests/40presence.pl#L123) fails on the Dendron builds. (I haven't seen it on the Synapse-only builds, but that doesn't mean it doesn't happen).

Test log:

not ok 297 Newly created users see their own presence in /initialSync (SYT-34)
# Expected to find my own presence at tests/40presence.pl line 140.
# 0.235987: Registered new user ANON-322
# 0.326304: initialSync response
# {
# account_data => [],
# end => "s1762_699_11_10_2_1_1",
# presence => [],
# receipts => [],
# rooms => [],
# }

Synapse master log:

2016-11-28 13:16:11,902 - synapse.access.http.20001 - 59 - INFO - GET-14752 - 127.0.0.1 - 20001 - Received request: GET /_synapse/replication?timeout=30000&to_device=1&backfill=1&presence=699&tag_account_data=2&user_account_data=2&push_rules=1&events=1762&public_rooms=195&typing=11&receipts=10&room_account_data=2&caches=432
2016-11-28 13:16:12,273 - synapse.access.http.20001 - 59 - INFO - POST-14753 - 127.0.0.1 - 20001 - Received request: POST /_matrix/client/r0/register
2016-11-28 13:16:12,293 - synapse.handlers.auth - 165 - INFO - POST-14753 - Auth completed with creds: {'m.login.dummy': True}
2016-11-28 13:16:12,359 - synapse.handlers.auth - 410 - INFO - POST-14753 - Logging in user @ANON-322:127.84.48.2:20000 on device TJJJYBSLMM
2016-11-28 13:16:12,399 - synapse.replication.resource - 191 - INFO - GET-14737 - Replicating 1 rows of caches from 432 -> 433
2016-11-28 13:16:12,400 - synapse.replication.resource - 191 - INFO - GET-14738 - Replicating 1 rows of caches from 432 -> 433
2016-11-28 13:16:12,401 - synapse.replication.resource - 191 - INFO - GET-14752 - Replicating 1 rows of caches from 432 -> 433
2016-11-28 13:16:12,402 - synapse.replication.resource - 191 - INFO - GET-14751 - Replicating 1 rows of caches from 432 -> 433
2016-11-28 13:16:12,403 - synapse.replication.resource - 191 - INFO - GET-14740 - Replicating 1 rows of caches from 432 -> 433
2016-11-28 13:16:12,403 - synapse.replication.resource - 191 - INFO - GET-14735 - Replicating 1 rows of caches from 432 -> 433
2016-11-28 13:16:12,429 - synapse.access.http.20001 - 91 - INFO - GET-14737 - 127.0.0.1 - 20001 - {None} Processed request: 2321ms (11ms, 0ms) (0ms/1) 172B 200 "GET /_synapse/replication?backfill=1&timeout=30000&events=1762&public_rooms=195&caches=432 HTTP/1.1" "Synapse/0.18.5-rc2 (b=HEAD,8724483) https://127.84.48.2:20000"
2016-11-28 13:16:12,430 - synapse.access.http.20001 - 91 - INFO - GET-14738 - 127.0.0.1 - 20001 - {None} Processed request: 2312ms (15ms, 4ms) (1ms/1) 172B 200 "GET /_synapse/replication?timeout=30000&events=1762&backfill=1&caches=432 HTTP/1.1" "Synapse/0.18.5-rc2 (b=HEAD,8724483) https://127.84.48.2:20000"
2016-11-28 13:16:12,430 - synapse.access.http.20001 - 91 - INFO - GET-14752 - 127.0.0.1 - 20001 - {None} Processed request: 527ms (16ms, 0ms) (0ms/1) 172B 200 "GET /_synapse/replication?timeout=30000&to_device=1&backfill=1&presence=699&tag_account_data=2&user_account_data=2&push_rules=1&events=1762&public_rooms=195&typing=11&receipts=10&room_account_data=2&caches=432 HTTP/1.1" "Synapse/0.18.5-rc2 (b=HEAD,8724483) https://127.84.48.2:20000"
2016-11-28 13:16:12,431 - synapse.access.http.20001 - 91 - INFO - GET-14751 - 127.0.0.1 - 20001 - {None} Processed request: 569ms (4ms, 0ms) (0ms/1) 172B 200 "GET /_synapse/replication?timeout=30000&to_device=1&backfill=1&federation_ack=650&caches=432&events=1762&federation=650&receipts=10 HTTP/1.1" "Synapse/0.18.5-rc2 (b=HEAD,8724483) https://127.84.48.2:20000"
2016-11-28 13:16:12,431 - synapse.access.http.20001 - 91 - INFO - GET-14740 - 127.0.0.1 - 20001 - {None} Processed request: 2309ms (16ms, 7ms) (2ms/1) 172B 200 "GET /_synapse/replication?backfill=1&tag_account_data=2&user_account_data=2&events=1762&timeout=30000&pushers=6&caches=432&room_account_data=2&receipts=10 HTTP/1.1" "Synapse/0.18.5-rc2 (b=HEAD,8724483) https://127.84.48.2:20000"
2016-11-28 13:16:12,431 - synapse.access.http.20001 - 91 - INFO - GET-14735 - 127.0.0.1 - 20001 - {None} Processed request: 2327ms (20ms, 0ms) (1ms/1) 172B 200 "GET /_synapse/replication?backfill=1&timeout=30000&events=1762&public_rooms=195&caches=432 HTTP/1.1" "Synapse/0.18.5-rc2 (b=HEAD,8724483) https://127.84.48.2:20000"

Synchrotron log:

2016-11-28 13:16:12,420 - synapse.http.client - 87 - INFO -  - Sending request GET http://127.84.48.2:20001/_synapse/replication?timeout=30000&to_device=1&backfill=1&presence=699&tag_account_data=2&user_account_data=2&push_rules=1&events=1762&public_rooms=195&typing=11&receipts=10&room_account_data=2&caches=433
2016-11-28 13:16:12,455 - synapse.access.http.20005 - 59 - INFO - GET-635 - 127.0.0.1 - 20005 - Received request: GET /_matrix/client/r0/events?timeout=0&access_token=<redacted>
2016-11-28 13:16:12,465 - twisted - 154 - INFO -  - Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x6f52638>
2016-11-28 13:16:12,466 - synapse.http.client - 87 - INFO - GET-635 - Sending request POST http://127.84.48.2:20001/_synapse/replication/syncing_users
2016-11-28 13:16:12,466 - synapse.metrics - 162 - INFO - GET-635 - Collecting gc 0
2016-11-28 13:16:12,492 - twisted - 154 - INFO - GET-635 - Stopping factory <twisted.web.client._HTTP11ClientFactory instance at 0x6f52638>
2016-11-28 13:16:12,492 - synapse.http.client - 93 - INFO - GET-635 - Received response to  POST http://127.84.48.2:20001/_synapse/replication/syncing_users: 200
2016-11-28 13:16:12,499 - synapse.access.http.20005 - 91 - INFO - GET-635 - 127.0.0.1 - 20005 - {@ANON-322:127.84.48.2:20000} Processed request: 44ms (8ms, 3ms) (1ms/1) 74B 200 "GET /_matrix/client/r0/events?timeout=0&access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.41"
2016-11-28 13:16:12,505 - synapse.access.http.20005 - 59 - INFO - GET-636 - 127.0.0.1 - 20005 - Received request: GET /_matrix/client/r0/initialSync?access_token=<redacted>
2016-11-28 13:16:12,529 - twisted - 154 - INFO - GET-636 - Stopping factory <twisted.web.client._HTTP11ClientFactory instance at 0x4b60a28>
2016-11-28 13:16:12,530 - synapse.http.client - 93 - INFO -  - Received response to  GET http://127.84.48.2:20001/_synapse/replication?timeout=30000&to_device=1&backfill=1&presence=699&tag_account_data=2&user_account_data=2&push_rules=1&events=1762&public_rooms=195&typing=11&receipts=10&room_account_data=2&caches=43
2016-11-28 13:16:12,556 - twisted - 154 - INFO -  - Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x6f504d0>
2016-11-28 13:16:12,562 - synapse.http.client - 87 - INFO -  - Sending request GET http://127.84.48.2:20001/_synapse/replication?timeout=30000&to_device=1&backfill=1&presence=700&tag_account_data=2&user_account_data=2&push_rules=1&events=1762&public_rooms=195&typing=11&receipts=10&room_account_data=2&caches=433
2016-11-28 13:16:12,590 - synapse.access.http.20005 - 91 - INFO - GET-636 - 127.0.0.1 - 20005 - {@ANON-322:127.84.48.2:20000} Processed request: 85ms (16ms, 4ms) (4ms/2) 88B 200 "GET /_matrix/client/r0/initialSync?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.41"

Presumably related to https://matrix.org/jira/browse/SYT-34.