TestRestrictedRoomsRemoteJoin is flaky on Synapse Monolith

[anoadragon453]

I just had following test flake on me: https://buildkite.com/matrix-dot-org/synapse/builds/17313#b4af426b-92c0-49cd-8f82-445f3c46c6f3

I haven't investigated yet to see whether it's a Synapse issue or a Complement one.

CC @clokep

[clokep]

I wonder if we need to be waiting for something (joins?) to come down sync? Maybe I'll play with the torture settings in Synapse to reproduce this.

[clokep]

Test logs

=== RUN   TestRestrictedRoomsRemoteJoin

    client.go:327: POST /_matrix/client/r0/createRoom => 200 OK (262.194878ms)

    client.go:327: POST /_matrix/client/r0/createRoom => 200 OK (281.339455ms)

    client.go:327: PUT /_matrix/client/r0/rooms/!TSUYkJNmlhuUjHkKzU:hs1/state/org.matrix.msc1772.space.child/!axRzfYYvbjlmsBAGdx:hs1 => 200 OK (46.186672ms)

    msc3083_test.go:66: SendEventSynced waiting for event ID $JTrURWjz0sGU8uJkYDO2ZLm1fMOkUPnKEfAUyih6Xhw

    client.go:327: GET /_matrix/client/r0/sync => 200 OK (82.56312ms)

    client.go:327: POST /_matrix/client/r0/join/!axRzfYYvbjlmsBAGdx:hs1 => 403 Forbidden (398.032933ms)

    client.go:327: POST /_matrix/client/r0/join/!TSUYkJNmlhuUjHkKzU:hs1 => 200 OK (118.256211ms)

    client.go:327: POST /_matrix/client/r0/join/!axRzfYYvbjlmsBAGdx:hs1 => 200 OK (204.486203ms)

    client.go:327: POST /_matrix/client/r0/rooms/!axRzfYYvbjlmsBAGdx:hs1/leave => 200 OK (73.536272ms)

    client.go:327: POST /_matrix/client/r0/rooms/!TSUYkJNmlhuUjHkKzU:hs1/leave => 200 OK (81.558471ms)

    client.go:327: POST /_matrix/client/r0/join/!axRzfYYvbjlmsBAGdx:hs1 => 200 OK (531.87967ms)

    msc3083_test.go:25: CSAPI.MustDoWithStatusRaw POST http://172.17.0.1:49215/_matrix/client/r0/join/%21axRzfYYvbjlmsBAGdx:hs1?access_token=syt_Ym9i_gWbzZkqCcutSaHXBQTbq_0Ohh5T&server_name=hs1 returned HTTP 200, expected 403

2021/05/13 19:51:21 ============================================





2021/05/13 19:51:21 91de30d9493dac85c840a8885b944d4f373fa43dccf194e21f49dff8548fa29f : Server logs:

Signature ok

subject=CN = hs2

Getting CA Private Key

Config is missing macaroon_secret_key

2021-05-13 19:51:16,906 - twisted - 258 - INFO - main - Redirected stdout/stderr to logs

2021-05-13 19:51:16,906 - root - 325 - WARNING - main - ***** STARTING SERVER *****

2021-05-13 19:51:16,906 - root - 326 - WARNING - main - Server /usr/local/lib/python3.8/site-packages/synapse/app/homeserver.py version 1.34.0rc1

2021-05-13 19:51:16,907 - root - 327 - INFO - main - Server hostname: hs2

2021-05-13 19:51:16,907 - root - 328 - INFO - main - Instance name: master

2021-05-13 19:51:16,907 - synapse.app.homeserver - 357 - INFO - main - Setting up server

2021-05-13 19:51:16,907 - synapse.server - 278 - INFO - main - Setting up.

2021-05-13 19:51:16,917 - synapse.storage.databases - 49 - INFO - main - [database config 'master']: Checking database server

2021-05-13 19:51:16,917 - synapse.storage.databases - 52 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']

2021-05-13 19:51:16,917 - synapse.storage.prepare_database - 95 - INFO - main - ['main', 'state']: Checking existing schema version

2021-05-13 19:51:16,920 - synapse.storage.prepare_database - 100 - INFO - main - ['main', 'state']: Existing schema is 59 (+14 deltas)

2021-05-13 19:51:16,921 - synapse.storage.databases.main - 351 - INFO - main - Checking database for consistency with configuration...

2021-05-13 19:51:16,922 - synapse.storage.prepare_database - 378 - INFO - main - Applying schema deltas for v59

2021-05-13 19:51:16,923 - synapse.storage.prepare_database - 506 - INFO - main - Schema now up to date

2021-05-13 19:51:16,927 - synapse.storage.databases - 67 - INFO - main - [database config 'master']: Starting 'main' database

2021-05-13 19:51:16,927 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for public_room_list_stream(stream_id)

2021-05-13 19:51:16,927 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for device_lists_stream(stream_id)

2021-05-13 19:51:16,928 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for user_signature_stream(stream_id)

2021-05-13 19:51:16,928 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for device_lists_outbound_pokes(stream_id)

2021-05-13 19:51:16,928 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for e2e_cross_signing_keys(stream_id)

2021-05-13 19:51:16,928 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for event_reports(id)

2021-05-13 19:51:16,929 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for push_rules(id)

2021-05-13 19:51:16,929 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for push_rules_enable(id)

2021-05-13 19:51:16,929 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for local_group_updates(stream_id)

2021-05-13 19:51:16,930 - synapse.config.appservice - 56 - WARNING - main - Expected None to be a list of AS config files.

2021-05-13 19:51:16,930 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for receipts_linearized(stream_id)

2021-05-13 19:51:16,930 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for room_account_data(stream_id)

2021-05-13 19:51:16,931 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for room_tags_revisions(stream_id)

2021-05-13 19:51:16,931 - synapse.storage.databases.main.event_push_actions - 537 - INFO - main - Searching for stream ordering 1 month ago

2021-05-13 19:51:16,932 - synapse.storage.databases.main.event_push_actions - 541 - INFO - main - Found stream ordering 1 month ago: it's 2

2021-05-13 19:51:16,932 - synapse.storage.databases.main.event_push_actions - 544 - INFO - main - Searching for stream ordering 1 day ago

2021-05-13 19:51:16,932 - synapse.storage.databases.main.event_push_actions - 548 - INFO - main - Found stream ordering 1 day ago: it's 2

2021-05-13 19:51:16,933 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for events(stream_ordering)

2021-05-13 19:51:16,934 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for events(stream_ordering)

2021-05-13 19:51:16,934 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for ex_outlier_stream(event_stream_ordering)

2021-05-13 19:51:16,938 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for device_inbox(stream_id)

2021-05-13 19:51:16,941 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for pushers(id)

2021-05-13 19:51:16,941 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for deleted_pushers(stream_id)

2021-05-13 19:51:16,941 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for push_rules_stream(stream_id)

2021-05-13 19:51:16,943 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for presence_stream(stream_id)

2021-05-13 19:51:16,944 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for access_tokens(id)

2021-05-13 19:51:16,945 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'state' database

2021-05-13 19:51:16,946 - synapse.storage.databases - 99 - INFO - main - [database config 'master']: prepared

2021-05-13 19:51:16,946 - synapse.server - 281 - INFO - main - Finished setting up.

2021-05-13 19:51:16,959 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False

2021-05-13 19:51:16,965 - synapse.handlers.auth - 213 - INFO - main - Extra password_providers: []

2021-05-13 19:51:16,974 - synapse.federation.federation_server - 882 - INFO - main - Registering federation EDU handler for 'm.device_list_update'

2021-05-13 19:51:16,976 - synapse.federation.federation_server - 902 - INFO - main - Registering federation query handler for 'profile'

2021-05-13 19:51:16,985 - synapse.federation.federation_server - 882 - INFO - main - Registering federation EDU handler for 'm.presence'

2021-05-13 19:51:16,986 - synapse.federation.federation_server - 882 - INFO - main - Registering federation EDU handler for 'm.typing'

2021-05-13 19:51:16,993 - synapse.federation.federation_server - 902 - INFO - main - Registering federation query handler for 'directory'

2021-05-13 19:51:17,005 - synapse.app.homeserver - 118 - INFO - sentinel - Running

2021-05-13 19:51:17,007 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576

2021-05-13 19:51:17,008 - synapse.handlers.deactivate_account - 207 - INFO - user_parter_loop-0 - Starting user parter

2021-05-13 19:51:17,009 - synapse.config.tls - 513 - INFO - sentinel - Loading TLS key from /conf/server.tls.key

2021-05-13 19:51:17,009 - synapse.config.tls - 490 - INFO - sentinel - Loading TLS certificate from /conf/server.tls.crt

2021-05-13 19:51:17,032 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7fce87edc670> to path b'/health'

2021-05-13 19:51:17,032 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7fce87ee76d0> to path b'/_matrix/federation'

2021-05-13 19:51:17,033 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fce87473970> to path b'/_matrix/media/r0'

2021-05-13 19:51:17,033 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fce87473970> to path b'/_matrix/media/v1'

2021-05-13 19:51:17,033 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7fce87488760> to path b'/_matrix/key/v2'

2021-05-13 19:51:17,034 - twisted - 258 - INFO - sentinel - SynapseSite (TLS) starting on 8448

2021-05-13 19:51:17,034 - synapse.app.homeserver - 153 - INFO - sentinel - Synapse now listening on TCP port 8448 (TLS)

2021-05-13 19:51:17,067 - synapse.federation.federation_server - 882 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'

2021-05-13 19:51:17,068 - synapse.federation.federation_server - 882 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'

2021-05-13 19:51:17,068 - synapse.federation.federation_server - 902 - INFO - sentinel - Registering federation query handler for 'client_keys'

2021-05-13 19:51:17,070 - synapse.federation.federation_server - 882 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7fce8748e3d0> to path b'/health'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7fce8748eb80> to path b'/_matrix/client/api/v1'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7fce8748eb80> to path b'/_matrix/client/r0'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7fce8748eb80> to path b'/_matrix/client/unstable'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7fce8748eb80> to path b'/_matrix/client/v2_alpha'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7fce8748eb80> to path b'/_matrix/client/versions'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.well_known.WellKnownResource object at 0x7fce87456370> to path b'/.well-known/matrix/client'

2021-05-13 19:51:17,076 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7fce87456430> to path b'/_synapse/admin'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7fce8745b730> to path b'/_synapse/client/pick_idp'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fce8745b790> to path b'/_synapse/client/pick_username'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7fce8745bac0> to path b'/_synapse/client/new_user_consent'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7fce8745baf0> to path b'/_synapse/client/sso_register'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.8/site-packages/synapse/static') to path b'/_matrix/static'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fce87473970> to path b'/_matrix/media/r0'

2021-05-13 19:51:17,077 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fce87473970> to path b'/_matrix/media/v1'

2021-05-13 19:51:17,078 - twisted - 258 - INFO - sentinel - SynapseSite starting on 8008

2021-05-13 19:51:17,078 - synapse.app.homeserver - 162 - INFO - sentinel - Synapse now listening on TCP port 8008

2021-05-13 19:51:17,140 - synapse.storage.background_updates - 109 - INFO - background_updates-0 - Starting background schema updates

2021-05-13 19:51:17,141 - synapse.handlers.deactivate_account - 217 - INFO - user_parter_loop-0 - User parter finished: stopping

2021-05-13 19:51:17,144 - synapse.access.http.8008 - 387 - INFO - GET-0 - ::ffff:192.168.48.1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 394B 200 "GET /_matrix/client/versions HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:17,151 - synapse.push.pusherpool - 320 - INFO - start_pushers-0 - Started pushers

2021-05-13 19:51:18,143 - synapse.storage.background_updates - 232 - INFO - background_updates-0 - Starting update batch on background update 'add_rooms_room_version_column'

2021-05-13 19:51:18,148 - synapse.storage.background_updates - 268 - INFO - background_updates-0 - Running background update 'add_rooms_room_version_column'. Processed 100 items in 5ms. (total_rate=0/ms, current_rate=0/ms, total_updated=0, batch_size=100)

2021-05-13 19:51:19,150 - synapse.storage.background_updates - 232 - INFO - background_updates-0 - Starting update batch on background update 'current_state_events_membership'

2021-05-13 19:51:19,156 - synapse.storage.background_updates - 268 - INFO - background_updates-0 - Running background update 'current_state_events_membership'. Processed 6 items in 5ms. (total_rate=0/ms, current_rate=0/ms, total_updated=0, batch_size=100)

2021-05-13 19:51:20,158 - synapse.storage.background_updates - 232 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'

2021-05-13 19:51:20,160 - synapse.storage.databases.main.state - 409 - INFO - background_updates-0 - skipping rooms which are being created: set()

2021-05-13 19:51:20,160 - synapse.storage.databases.main.state - 425 - INFO - background_updates-0 - Deleting current state left rooms: set()

2021-05-13 19:51:20,164 - synapse.storage.background_updates - 268 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 100 items in 5ms. (total_rate=0/ms, current_rate=0/ms, total_updated=0, batch_size=100)

2021-05-13 19:51:20,382 - synapse.http.servlet - 218 - WARNING - POST-1 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0)

2021-05-13 19:51:20,390 - synapse.http.federation.well_known_resolver - 254 - INFO - POST-1 - Fetching https://hs1/.well-known/matrix/server

2021-05-13 19:51:20,665 - synapse.federation.transport.server - 406 - INFO - PUT-2 - Received txn 1620935479521 from hs1. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:20,682 - synapse.access.https.8448 - 387 - INFO - PUT-2 - ::ffff:192.168.48.3 - 8448 - {hs1} Processed request: 0.020sec/-0.000sec (0.001sec, 0.002sec) (0.002sec/0.011sec/6) 11B 200 "PUT /_matrix/federation/v1/send/1620935479521 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,693 - synapse.http.federation.well_known_resolver - 285 - INFO - POST-1 - Error fetching https://hs1/.well-known/matrix/server: Connection was refused by other side: 111: Connection refused.

2021-05-13 19:51:20,694 - twisted - 258 - INFO - POST-1 - b'/etc/resolv.conf' changed, reparsing

2021-05-13 19:51:20,695 - twisted - 258 - INFO - POST-1 - Resolver added ('127.0.0.11', 53) to server list

2021-05-13 19:51:20,759 - synapse.http.matrixfederationclient - 227 - INFO - POST-1 - {GET-O-1} [hs1] Completed request: 200 OK in 0.37 secs - GET matrix://hs1/_matrix/federation/v1/make_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083

2021-05-13 19:51:20,774 - synapse.http.matrixfederationclient - 534 - INFO - POST-1 - {PUT-O-2} [hs1] Got response headers: 403 Forbidden

2021-05-13 19:51:20,774 - synapse.http.matrixfederationclient - 612 - WARNING - POST-1 - {PUT-O-2} [hs1] Request failed: PUT matrix://hs1/_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24ZuZ2iT0wsttd51BRmbJVkpmb78dPGe2LcL7RApkwhao: HttpResponseException('403: Forbidden')

2021-05-13 19:51:20,775 - synapse.http.server - 88 - INFO - POST-1 - <SynapseRequest at 0x7fce8816bdc0 method='POST' uri='/_matrix/client/r0/join/%21axRzfYYvbjlmsBAGdx:hs1?access_token=<redacted>&server_name=hs1' clientproto='HTTP/1.1' site='8008'> SynapseError: 403 - You do not belong to any of the required spaces to join this room.

2021-05-13 19:51:20,775 - synapse.access.http.8008 - 387 - INFO - POST-1 - ::ffff:192.168.48.1 - 8008 - {@bob:hs2} Processed request: 0.395sec/-0.000sec (0.004sec, 0.000sec) (0.003sec/0.002sec/11) 102B 403 "POST /_matrix/client/r0/join/%21axRzfYYvbjlmsBAGdx:hs1?access_token=<redacted>&server_name=hs1 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:20,778 - synapse.http.servlet - 218 - WARNING - POST-3 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0)

2021-05-13 19:51:20,795 - synapse.http.matrixfederationclient - 227 - INFO - POST-3 - {GET-O-3} [hs1] Completed request: 200 OK in 0.01 secs - GET matrix://hs1/_matrix/federation/v1/make_join/%21TSUYkJNmlhuUjHkKzU%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083

2021-05-13 19:51:20,828 - synapse.federation.transport.server - 406 - INFO - PUT-4 - Received txn 1620935479522 from hs1. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:20,836 - synapse.access.https.8448 - 387 - INFO - PUT-4 - ::ffff:192.168.48.3 - 8448 - {hs1} Processed request: 0.008sec/-0.000sec (0.002sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1620935479522 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,838 - synapse.http.matrixfederationclient - 227 - INFO - POST-3 - {PUT-O-4} [hs1] Completed request: 200 OK in 0.04 secs - PUT matrix://hs1/_matrix/federation/v2/send_join/%21TSUYkJNmlhuUjHkKzU%3Ahs1/%24BVGXKlha63cshzXCNX3aMvnFlXQb4iqnbOeJY3IZ9xQ

2021-05-13 19:51:20,893 - synapse.access.http.8008 - 387 - INFO - POST-3 - ::ffff:192.168.48.1 - 8008 - {@bob:hs2} Processed request: 0.116sec/-0.000sec (0.008sec, 0.000sec) (0.003sec/0.014sec/11) 37B 200 "POST /_matrix/client/r0/join/%21TSUYkJNmlhuUjHkKzU:hs1?access_token=<redacted>&server_name=hs1 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:20,898 - synapse.http.servlet - 218 - WARNING - POST-5 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0)

2021-05-13 19:51:20,928 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-0 - TX [hs1] {1620935476963} Sending transaction [1620935476963], (PDUs: 0, EDUs: 1)

2021-05-13 19:51:20,952 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-0 - {PUT-O-5} [hs1] Completed request: 200 OK in 0.02 secs - PUT matrix://hs1/_matrix/federation/v1/send/1620935476963

2021-05-13 19:51:20,952 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-0 - TX [hs1] {1620935476963} got 200 response

2021-05-13 19:51:20,999 - synapse.http.matrixfederationclient - 227 - INFO - POST-5 - {GET-O-6} [hs1] Completed request: 200 OK in 0.07 secs - GET matrix://hs1/_matrix/federation/v1/make_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083

2021-05-13 19:51:21,038 - synapse.federation.transport.server - 406 - INFO - PUT-6 - Received txn 1620935479523 from hs1. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,045 - synapse.access.https.8448 - 387 - INFO - PUT-6 - ::ffff:192.168.48.3 - 8448 - {hs1} Processed request: 0.008sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1620935479523 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,049 - synapse.http.matrixfederationclient - 227 - INFO - POST-5 - {PUT-O-7} [hs1] Completed request: 200 OK in 0.05 secs - PUT matrix://hs1/_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24bAwbUMCXiR9HC9PwAuIXCD5nqPiuN4RZJ7xim6f-rek

2021-05-13 19:51:21,098 - synapse.access.http.8008 - 387 - INFO - POST-5 - ::ffff:192.168.48.1 - 8008 - {@bob:hs2} Processed request: 0.201sec/-0.000sec (0.013sec, 0.001sec) (0.027sec/0.015sec/11) 37B 200 "POST /_matrix/client/r0/join/%21axRzfYYvbjlmsBAGdx:hs1?access_token=<redacted>&server_name=hs1 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:21,101 - synapse.http.servlet - 218 - WARNING - POST-7 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0)

2021-05-13 19:51:21,111 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-1 - TX [hs1] {1620935476964} Sending transaction [1620935476964], (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,125 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-1 - {PUT-O-8} [hs1] Completed request: 200 OK in 0.01 secs - PUT matrix://hs1/_matrix/federation/v1/send/1620935476964

2021-05-13 19:51:21,125 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-1 - TX [hs1] {1620935476964} got 200 response

2021-05-13 19:51:21,159 - synapse.storage.persist_events - 518 - INFO - persist_events-4 - Server no longer in room !axRzfYYvbjlmsBAGdx:hs1

2021-05-13 19:51:21,165 - synapse.storage.background_updates - 232 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'

2021-05-13 19:51:21,172 - synapse.access.http.8008 - 387 - INFO - POST-7 - ::ffff:192.168.48.1 - 8008 - {@bob:hs2} Processed request: 0.071sec/-0.000sec (0.004sec, 0.001sec) (0.031sec/0.008sec/7) 2B 200 "POST /_matrix/client/r0/rooms/%21axRzfYYvbjlmsBAGdx:hs1/leave?access_token=<redacted> HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:21,173 - synapse.storage.databases.main.state - 409 - INFO - background_updates-0 - skipping rooms which are being created: set()

2021-05-13 19:51:21,173 - synapse.storage.databases.main.state - 425 - INFO - background_updates-0 - Deleting current state left rooms: set()

2021-05-13 19:51:21,176 - synapse.http.servlet - 218 - WARNING - POST-8 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0)

2021-05-13 19:51:21,178 - synapse.storage.background_updates - 268 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 2000 items in 9ms. (total_rate=20.0/ms, current_rate=20.0/ms, total_updated=100, batch_size=2000)

2021-05-13 19:51:21,201 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-2 - TX [hs1] {1620935476965} Sending transaction [1620935476965], (PDUs: 1, EDUs: 0)

2021-05-13 19:51:21,236 - synapse.storage.persist_events - 518 - INFO - persist_events-5 - Server no longer in room !TSUYkJNmlhuUjHkKzU:hs1

2021-05-13 19:51:21,243 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-2 - {PUT-O-9} [hs1] Completed request: 200 OK in 0.04 secs - PUT matrix://hs1/_matrix/federation/v1/send/1620935476965

2021-05-13 19:51:21,243 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-2 - TX [hs1] {1620935476965} got 200 response

2021-05-13 19:51:21,254 - synapse.access.http.8008 - 387 - INFO - POST-8 - ::ffff:192.168.48.1 - 8008 - {@bob:hs2} Processed request: 0.079sec/-0.000sec (0.003sec, 0.003sec) (0.032sec/0.009sec/7) 2B 200 "POST /_matrix/client/r0/rooms/%21TSUYkJNmlhuUjHkKzU:hs1/leave?access_token=<redacted> HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:21,258 - synapse.http.servlet - 218 - WARNING - POST-9 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0)

2021-05-13 19:51:21,282 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-3 - TX [hs1] {1620935476966} Sending transaction [1620935476966], (PDUs: 1, EDUs: 0)

2021-05-13 19:51:21,310 - synapse.http.matrixfederationclient - 227 - INFO - POST-9 - {GET-O-11} [hs1] Completed request: 200 OK in 0.02 secs - GET matrix://hs1/_matrix/federation/v1/make_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083

2021-05-13 19:51:21,353 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-3 - {PUT-O-10} [hs1] Completed request: 200 OK in 0.07 secs - PUT matrix://hs1/_matrix/federation/v1/send/1620935476966

2021-05-13 19:51:21,354 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-3 - TX [hs1] {1620935476966} got 200 response

2021-05-13 19:51:21,392 - synapse.federation.transport.server - 406 - INFO - PUT-10 - Received txn 1620935479524 from hs1. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,402 - synapse.access.https.8448 - 387 - INFO - PUT-10 - ::ffff:192.168.48.3 - 8448 - {hs1} Processed request: 0.011sec/-0.000sec (0.001sec, 0.002sec) (0.004sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1620935479524 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,405 - synapse.http.matrixfederationclient - 227 - INFO - POST-9 - {PUT-O-12} [hs1] Completed request: 200 OK in 0.09 secs - PUT matrix://hs1/_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24-tVGvqQJllTivBFlULba2YP1SxMa8oRYVV77zs7WBFg

2021-05-13 19:51:21,414 - synapse.http.federation.well_known_resolver - 254 - INFO - POST-9 - Fetching https://hs2/.well-known/matrix/server

2021-05-13 19:51:21,717 - synapse.http.federation.well_known_resolver - 285 - INFO - POST-9 - Error fetching https://hs2/.well-known/matrix/server: Connection was refused by other side: 111: Connection refused.

2021-05-13 19:51:21,729 - synapse.access.https.8448 - 387 - INFO - GET-11 - ::ffff:192.168.48.2 - 8448 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 367B 200 "GET /_matrix/key/v2/server/ed25519%3Aa_OjTR HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,730 - synapse.http.matrixfederationclient - 227 - INFO - POST-9 - {GET-O-13} [hs2] Completed request: 200 OK in 0.32 secs - GET matrix://hs2/_matrix/key/v2/server/ed25519%3Aa_OjTR

2021-05-13 19:51:21,785 - synapse.access.http.8008 - 387 - INFO - POST-9 - ::ffff:192.168.48.1 - 8008 - {@bob:hs2} Processed request: 0.528sec/-0.000sec (0.013sec, 0.002sec) (0.033sec/0.024sec/14) 37B 200 "POST /_matrix/client/r0/join/%21axRzfYYvbjlmsBAGdx:hs1?access_token=<redacted>&server_name=hs1 HTTP/1.1" "Go-http-client/1.1" [1 dbevts]

2021/05/13 19:51:21 ============== 91de30d9493dac85c840a8885b944d4f373fa43dccf194e21f49dff8548fa29f : END LOGS ==============





2021/05/13 19:51:22 ============================================





2021/05/13 19:51:22 84927f8691a7a4e679cdca20202582d28970244d15f6b820190cbcad526b0892 : Server logs:

Signature ok

subject=CN = hs1

Getting CA Private Key

Config is missing macaroon_secret_key

2021-05-13 19:51:19,464 - twisted - 258 - INFO - main - Redirected stdout/stderr to logs

2021-05-13 19:51:19,464 - root - 325 - WARNING - main - ***** STARTING SERVER *****

2021-05-13 19:51:19,464 - root - 326 - WARNING - main - Server /usr/local/lib/python3.8/site-packages/synapse/app/homeserver.py version 1.34.0rc1

2021-05-13 19:51:19,464 - root - 327 - INFO - main - Server hostname: hs1

2021-05-13 19:51:19,464 - root - 328 - INFO - main - Instance name: master

2021-05-13 19:51:19,464 - synapse.app.homeserver - 357 - INFO - main - Setting up server

2021-05-13 19:51:19,465 - synapse.server - 278 - INFO - main - Setting up.

2021-05-13 19:51:19,474 - synapse.storage.databases - 49 - INFO - main - [database config 'master']: Checking database server

2021-05-13 19:51:19,474 - synapse.storage.databases - 52 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']

2021-05-13 19:51:19,475 - synapse.storage.prepare_database - 95 - INFO - main - ['main', 'state']: Checking existing schema version

2021-05-13 19:51:19,477 - synapse.storage.prepare_database - 100 - INFO - main - ['main', 'state']: Existing schema is 59 (+14 deltas)

2021-05-13 19:51:19,479 - synapse.storage.databases.main - 351 - INFO - main - Checking database for consistency with configuration...

2021-05-13 19:51:19,480 - synapse.storage.prepare_database - 378 - INFO - main - Applying schema deltas for v59

2021-05-13 19:51:19,481 - synapse.storage.prepare_database - 506 - INFO - main - Schema now up to date

2021-05-13 19:51:19,485 - synapse.storage.databases - 67 - INFO - main - [database config 'master']: Starting 'main' database

2021-05-13 19:51:19,485 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for public_room_list_stream(stream_id)

2021-05-13 19:51:19,486 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for device_lists_stream(stream_id)

2021-05-13 19:51:19,486 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for user_signature_stream(stream_id)

2021-05-13 19:51:19,486 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for device_lists_outbound_pokes(stream_id)

2021-05-13 19:51:19,486 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for e2e_cross_signing_keys(stream_id)

2021-05-13 19:51:19,486 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for event_reports(id)

2021-05-13 19:51:19,487 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for push_rules(id)

2021-05-13 19:51:19,487 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for push_rules_enable(id)

2021-05-13 19:51:19,487 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for local_group_updates(stream_id)

2021-05-13 19:51:19,488 - synapse.config.appservice - 56 - WARNING - main - Expected None to be a list of AS config files.

2021-05-13 19:51:19,488 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for receipts_linearized(stream_id)

2021-05-13 19:51:19,488 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for room_account_data(stream_id)

2021-05-13 19:51:19,488 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for room_tags_revisions(stream_id)

2021-05-13 19:51:19,489 - synapse.storage.databases.main.event_push_actions - 537 - INFO - main - Searching for stream ordering 1 month ago

2021-05-13 19:51:19,489 - synapse.storage.databases.main.event_push_actions - 541 - INFO - main - Found stream ordering 1 month ago: it's 2

2021-05-13 19:51:19,489 - synapse.storage.databases.main.event_push_actions - 544 - INFO - main - Searching for stream ordering 1 day ago

2021-05-13 19:51:19,490 - synapse.storage.databases.main.event_push_actions - 548 - INFO - main - Found stream ordering 1 day ago: it's 2

2021-05-13 19:51:19,491 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for events(stream_ordering)

2021-05-13 19:51:19,491 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for events(stream_ordering)

2021-05-13 19:51:19,492 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for ex_outlier_stream(event_stream_ordering)

2021-05-13 19:51:19,496 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for device_inbox(stream_id)

2021-05-13 19:51:19,499 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for pushers(id)

2021-05-13 19:51:19,499 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for deleted_pushers(stream_id)

2021-05-13 19:51:19,499 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for push_rules_stream(stream_id)

2021-05-13 19:51:19,501 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for presence_stream(stream_id)

2021-05-13 19:51:19,503 - synapse.storage.util.id_generators - 55 - INFO - main - initialising stream generator for access_tokens(id)

2021-05-13 19:51:19,504 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'state' database

2021-05-13 19:51:19,504 - synapse.storage.databases - 99 - INFO - main - [database config 'master']: prepared

2021-05-13 19:51:19,505 - synapse.server - 281 - INFO - main - Finished setting up.

2021-05-13 19:51:19,517 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False

2021-05-13 19:51:19,524 - synapse.handlers.auth - 213 - INFO - main - Extra password_providers: []

2021-05-13 19:51:19,533 - synapse.federation.federation_server - 882 - INFO - main - Registering federation EDU handler for 'm.device_list_update'

2021-05-13 19:51:19,535 - synapse.federation.federation_server - 902 - INFO - main - Registering federation query handler for 'profile'

2021-05-13 19:51:19,544 - synapse.federation.federation_server - 882 - INFO - main - Registering federation EDU handler for 'm.presence'

2021-05-13 19:51:19,545 - synapse.federation.federation_server - 882 - INFO - main - Registering federation EDU handler for 'm.typing'

2021-05-13 19:51:19,552 - synapse.federation.federation_server - 902 - INFO - main - Registering federation query handler for 'directory'

2021-05-13 19:51:19,564 - synapse.app.homeserver - 118 - INFO - sentinel - Running

2021-05-13 19:51:19,566 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576

2021-05-13 19:51:19,567 - synapse.handlers.deactivate_account - 207 - INFO - user_parter_loop-0 - Starting user parter

2021-05-13 19:51:19,568 - synapse.config.tls - 513 - INFO - sentinel - Loading TLS key from /conf/server.tls.key

2021-05-13 19:51:19,568 - synapse.config.tls - 490 - INFO - sentinel - Loading TLS certificate from /conf/server.tls.crt

2021-05-13 19:51:19,591 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7faa8b9c4640> to path b'/health'

2021-05-13 19:51:19,591 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7faa8b9cd6a0> to path b'/_matrix/federation'

2021-05-13 19:51:19,592 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7faa8af5b940> to path b'/_matrix/media/r0'

2021-05-13 19:51:19,592 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7faa8af5b940> to path b'/_matrix/media/v1'

2021-05-13 19:51:19,592 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7faa8af6f730> to path b'/_matrix/key/v2'

2021-05-13 19:51:19,593 - twisted - 258 - INFO - sentinel - SynapseSite (TLS) starting on 8448

2021-05-13 19:51:19,594 - synapse.app.homeserver - 153 - INFO - sentinel - Synapse now listening on TCP port 8448 (TLS)

2021-05-13 19:51:19,627 - synapse.federation.federation_server - 882 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'

2021-05-13 19:51:19,628 - synapse.federation.federation_server - 882 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'

2021-05-13 19:51:19,628 - synapse.federation.federation_server - 902 - INFO - sentinel - Registering federation query handler for 'client_keys'

2021-05-13 19:51:19,629 - synapse.federation.federation_server - 882 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7faa8af6fb80> to path b'/health'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7faa8af7bb50> to path b'/_matrix/client/api/v1'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7faa8af7bb50> to path b'/_matrix/client/r0'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7faa8af7bb50> to path b'/_matrix/client/unstable'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7faa8af7bb50> to path b'/_matrix/client/v2_alpha'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7faa8af7bb50> to path b'/_matrix/client/versions'

2021-05-13 19:51:19,636 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.well_known.WellKnownResource object at 0x7faa8af40340> to path b'/.well-known/matrix/client'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7faa8af40400> to path b'/_synapse/admin'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7faa8af44700> to path b'/_synapse/client/pick_idp'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7faa8af44760> to path b'/_synapse/client/pick_username'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7faa8af44a90> to path b'/_synapse/client/new_user_consent'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7faa8af44ac0> to path b'/_synapse/client/sso_register'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.8/site-packages/synapse/static') to path b'/_matrix/static'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7faa8af5b940> to path b'/_matrix/media/r0'

2021-05-13 19:51:19,637 - synapse.util.httpresourcetree - 46 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7faa8af5b940> to path b'/_matrix/media/v1'

2021-05-13 19:51:19,638 - twisted - 258 - INFO - sentinel - SynapseSite starting on 8008

2021-05-13 19:51:19,638 - synapse.app.homeserver - 162 - INFO - sentinel - Synapse now listening on TCP port 8008

2021-05-13 19:51:19,699 - synapse.storage.background_updates - 109 - INFO - background_updates-0 - Starting background schema updates

2021-05-13 19:51:19,699 - synapse.handlers.deactivate_account - 217 - INFO - user_parter_loop-0 - User parter finished: stopping

2021-05-13 19:51:19,702 - synapse.push.pusherpool - 320 - INFO - start_pushers-0 - Started pushers

2021-05-13 19:51:19,703 - synapse.access.http.8008 - 387 - INFO - GET-0 - ::ffff:192.168.48.1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 394B 200 "GET /_matrix/client/versions HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:19,966 - synapse.access.http.8008 - 387 - INFO - POST-1 - ::ffff:192.168.48.1 - 8008 - {@alice:hs1} Processed request: 0.258sec/-0.000sec (0.010sec, 0.006sec) (0.103sec/0.042sec/37) 37B 200 "POST /_matrix/client/r0/createRoom?access_token=<redacted> HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:20,247 - synapse.access.http.8008 - 387 - INFO - POST-2 - ::ffff:192.168.48.1 - 8008 - {@alice:hs1} Processed request: 0.278sec/-0.000sec (0.015sec, 0.003sec) (0.124sec/0.045sec/32) 37B 200 "POST /_matrix/client/r0/createRoom?access_token=<redacted> HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:20,293 - synapse.access.http.8008 - 387 - INFO - PUT-3 - ::ffff:192.168.48.1 - 8008 - {@alice:hs1} Processed request: 0.043sec/-0.000sec (0.001sec, 0.001sec) (0.018sec/0.006sec/4) 59B 200 "PUT /_matrix/client/r0/rooms/%21TSUYkJNmlhuUjHkKzU:hs1/state/org.matrix.msc1772.space.child/%21axRzfYYvbjlmsBAGdx:hs1?access_token=<redacted> HTTP/1.1" "Go-http-client/1.1" [0 dbevts]

2021-05-13 19:51:20,330 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-0 - TX [hs2] {1620935479521} Sending transaction [1620935479521], (PDUs: 0, EDUs: 1)

2021-05-13 19:51:20,331 - synapse.http.federation.well_known_resolver - 254 - INFO - federation_transaction_transmission_loop-0 - Fetching https://hs2/.well-known/matrix/server

2021-05-13 19:51:20,376 - synapse.access.http.8008 - 387 - INFO - GET-4 - ::ffff:192.168.48.1 - 8008 - {@alice:hs1} Processed request: 0.080sec/-0.000sec (0.019sec, 0.000sec) (0.048sec/0.028sec/44) 10380B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&timeout=1000 HTTP/1.1" "Go-http-client/1.1" [7 dbevts]

2021-05-13 19:51:20,636 - synapse.http.federation.well_known_resolver - 285 - INFO - federation_transaction_transmission_loop-0 - Error fetching https://hs2/.well-known/matrix/server: Connection was refused by other side: 111: Connection refused.

2021-05-13 19:51:20,637 - twisted - 258 - INFO - federation_transaction_transmission_loop-0 - b'/etc/resolv.conf' changed, reparsing

2021-05-13 19:51:20,637 - twisted - 258 - INFO - federation_transaction_transmission_loop-0 - Resolver added ('127.0.0.11', 53) to server list

2021-05-13 19:51:20,701 - synapse.storage.background_updates - 232 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'

2021-05-13 19:51:20,703 - synapse.storage.databases.main.state - 409 - INFO - background_updates-0 - skipping rooms which are being created: set()

2021-05-13 19:51:20,703 - synapse.storage.databases.main.state - 425 - INFO - background_updates-0 - Deleting current state left rooms: set()

2021-05-13 19:51:20,710 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-0 - {PUT-O-1} [hs2] Completed request: 200 OK in 0.38 secs - PUT matrix://hs2/_matrix/federation/v1/send/1620935479521

2021-05-13 19:51:20,711 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-0 - TX [hs2] {1620935479521} got 200 response

2021-05-13 19:51:20,711 - synapse.storage.background_updates - 268 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 100 items in 9ms. (total_rate=0/ms, current_rate=0/ms, total_updated=0, batch_size=100)

2021-05-13 19:51:20,724 - synapse.access.https.8448 - 387 - INFO - GET-5 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.012sec/-0.000sec (0.002sec, 0.000sec) (0.001sec/0.005sec/5) 691B 200 "GET /_matrix/federation/v1/make_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,764 - synapse.crypto.keyring - 315 - INFO - PUT-6 - Waiting for existing lookups for ['hs2'] to complete [loop 1]

2021-05-13 19:51:20,772 - synapse.http.server - 88 - INFO - PUT-6 - <SynapseRequest at 0x7faa8ae372b0 method='PUT' uri='/_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24ZuZ2iT0wsttd51BRmbJVkpmb78dPGe2LcL7RApkwhao' clientproto='HTTP/1.1' site='8448'> SynapseError: 403 - You do not belong to any of the required spaces to join this room.

2021-05-13 19:51:20,772 - synapse.access.https.8448 - 387 - INFO - PUT-6 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.009sec/-0.000sec (0.002sec, 0.000sec) (0.000sec/0.005sec/2) 102B 403 "PUT /_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24ZuZ2iT0wsttd51BRmbJVkpmb78dPGe2LcL7RApkwhao HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,793 - synapse.access.https.8448 - 387 - INFO - GET-7 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.009sec/-0.000sec (0.001sec, 0.000sec) (0.001sec/0.004sec/4) 674B 200 "GET /_matrix/federation/v1/make_join/%21TSUYkJNmlhuUjHkKzU%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,800 - synapse.crypto.keyring - 315 - INFO - PUT-8 - Waiting for existing lookups for ['hs2'] to complete [loop 1]

2021-05-13 19:51:20,824 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-1 - TX [hs2] {1620935479522} Sending transaction [1620935479522], (PDUs: 0, EDUs: 1)

2021-05-13 19:51:20,835 - synapse.access.https.8448 - 387 - INFO - PUT-8 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.036sec/-0.000sec (0.004sec, 0.000sec) (0.009sec/0.007sec/4) 6592B 200 "PUT /_matrix/federation/v2/send_join/%21TSUYkJNmlhuUjHkKzU%3Ahs1/%24BVGXKlha63cshzXCNX3aMvnFlXQb4iqnbOeJY3IZ9xQ HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,837 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-1 - {PUT-O-2} [hs2] Completed request: 200 OK in 0.01 secs - PUT matrix://hs2/_matrix/federation/v1/send/1620935479522

2021-05-13 19:51:20,838 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-1 - TX [hs2] {1620935479522} got 200 response

2021-05-13 19:51:20,932 - synapse.federation.transport.server - 406 - INFO - PUT-9 - Received txn 1620935476963 from hs2. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:20,948 - synapse.access.https.8448 - 387 - INFO - PUT-9 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.018sec/-0.000sec (0.002sec, 0.002sec) (0.001sec/0.010sec/4) 11B 200 "PUT /_matrix/federation/v1/send/1620935476963 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:20,963 - synapse.access.https.8448 - 387 - INFO - GET-10 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.012sec/-0.000sec (0.003sec, 0.000sec) (0.002sec/0.005sec/3) 691B 200 "GET /_matrix/federation/v1/make_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,004 - synapse.crypto.keyring - 315 - INFO - PUT-11 - Waiting for existing lookups for ['hs2'] to complete [loop 1]

2021-05-13 19:51:21,033 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-2 - TX [hs2] {1620935479523} Sending transaction [1620935479523], (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,043 - synapse.access.https.8448 - 387 - INFO - PUT-11 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.041sec/-0.000sec (0.004sec, 0.001sec) (0.009sec/0.007sec/4) 6009B 200 "PUT /_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24bAwbUMCXiR9HC9PwAuIXCD5nqPiuN4RZJ7xim6f-rek HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,047 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-2 - {PUT-O-3} [hs2] Completed request: 200 OK in 0.01 secs - PUT matrix://hs2/_matrix/federation/v1/send/1620935479523

2021-05-13 19:51:21,048 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-2 - TX [hs2] {1620935479523} got 200 response

2021-05-13 19:51:21,116 - synapse.federation.transport.server - 406 - INFO - PUT-12 - Received txn 1620935476964 from hs2. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,123 - synapse.access.https.8448 - 387 - INFO - PUT-12 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.008sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1620935476964 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,205 - synapse.federation.transport.server - 406 - INFO - PUT-13 - Received txn 1620935476965 from hs2. (PDUs: 1, EDUs: 0)

2021-05-13 19:51:21,208 - synapse.handlers.federation - 201 - INFO - PUT-13-!axRzfYYvbjlmsBAGdx:hs1-$zKiNYzT6uE2Kp2ZxdTX4KrPisteh7bbwQkAJxwU6guA - handling received PDU: <FrozenEventV3 event_id='$zKiNYzT6uE2Kp2ZxdTX4KrPisteh7bbwQkAJxwU6guA', type='m.room.member', state_key='@bob:hs2'>

2021-05-13 19:51:21,241 - synapse.access.https.8448 - 387 - INFO - PUT-13 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.037sec/-0.000sec (0.005sec, 0.000sec) (0.003sec/0.009sec/7) 60B 200 "PUT /_matrix/federation/v1/send/1620935476965 HTTP/1.1" "Synapse/1.34.0rc1" [1 dbevts]

2021-05-13 19:51:21,287 - synapse.federation.transport.server - 406 - INFO - PUT-14 - Received txn 1620935476966 from hs2. (PDUs: 1, EDUs: 0)

2021-05-13 19:51:21,291 - synapse.handlers.federation - 201 - INFO - PUT-14-!TSUYkJNmlhuUjHkKzU:hs1-$cwEKRvJ92OetSD18D0nZlpFx-scbbrP6ItdLFcR7RBM - handling received PDU: <FrozenEventV3 event_id='$cwEKRvJ92OetSD18D0nZlpFx-scbbrP6ItdLFcR7RBM', type='m.room.member', state_key='@bob:hs2'>

2021-05-13 19:51:21,308 - synapse.access.https.8448 - 387 - INFO - GET-15 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.015sec/-0.000sec (0.005sec, 0.000sec) (0.002sec/0.007sec/4) 802B 200 "GET /_matrix/federation/v1/make_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%40bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=org.matrix.msc3083 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,321 - synapse.crypto.keyring - 315 - INFO - PUT-16 - Waiting for existing lookups for ['hs2'] to complete [loop 1]

2021-05-13 19:51:21,352 - synapse.access.https.8448 - 387 - INFO - PUT-14 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.066sec/-0.000sec (0.004sec, 0.006sec) (0.012sec/0.016sec/7) 60B 200 "PUT /_matrix/federation/v1/send/1620935476966 HTTP/1.1" "Synapse/1.34.0rc1" [1 dbevts]

2021-05-13 19:51:21,388 - synapse.federation.sender.transaction_manager - 118 - INFO - federation_transaction_transmission_loop-3 - TX [hs2] {1620935479524} Sending transaction [1620935479524], (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,400 - synapse.access.https.8448 - 387 - INFO - PUT-16 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.080sec/-0.000sec (0.007sec, 0.002sec) (0.021sec/0.015sec/5) 8239B 200 "PUT /_matrix/federation/v2/send_join/%21axRzfYYvbjlmsBAGdx%3Ahs1/%24-tVGvqQJllTivBFlULba2YP1SxMa8oRYVV77zs7WBFg HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021-05-13 19:51:21,404 - synapse.http.matrixfederationclient - 227 - INFO - federation_transaction_transmission_loop-3 - {PUT-O-4} [hs2] Completed request: 200 OK in 0.02 secs - PUT matrix://hs2/_matrix/federation/v1/send/1620935479524

2021-05-13 19:51:21,405 - synapse.federation.sender.transaction_manager - 158 - INFO - federation_transaction_transmission_loop-3 - TX [hs2] {1620935479524} got 200 response

2021-05-13 19:51:21,712 - synapse.storage.background_updates - 232 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'

2021-05-13 19:51:21,721 - synapse.storage.background_updates - 268 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 1111 items in 6ms. (total_rate=11.11111111111111/ms, current_rate=11.11111111111111/ms, total_updated=100, batch_size=1111)

2021-05-13 19:51:21,808 - synapse.federation.transport.server - 406 - INFO - PUT-17 - Received txn 1620935476967 from hs2. (PDUs: 0, EDUs: 1)

2021-05-13 19:51:21,816 - synapse.access.https.8448 - 387 - INFO - PUT-17 - ::ffff:192.168.48.2 - 8448 - {hs2} Processed request: 0.009sec/-0.000sec (0.003sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1620935476967 HTTP/1.1" "Synapse/1.34.0rc1" [0 dbevts]

2021/05/13 19:51:22 ============== 84927f8691a7a4e679cdca20202582d28970244d15f6b820190cbcad526b0892 : END LOGS ==============

--- FAIL: TestRestrictedRoomsRemoteJoin (7.95s)

[clokep]

It looks like this is the bit of code that is running:

complement/tests/msc3083_test.go

Lines 83 to 92 in b6a7e0d

	failJoinRoom(t, bob, room, "hs1")
	// Join the space, attempt to join the room again, which now should succeed.
	bob.JoinRoom(t, space, []string{"hs1"})
	bob.JoinRoom(t, room, []string{"hs1"})
	// Leaving the room works and the user is unable to re-join.
	bob.LeaveRoom(t, room)
	bob.LeaveRoom(t, space)
	failJoinRoom(t, bob, room, "hs1")

I'm guessing that we're trying to re-join the room before the leave has been persisted (or something of that nature)?

[anoadragon453]

I see some more flakiness happening with the TestClientSpacesSummary, TestFederatedClientSpaces and TestRestrictedRoomsRemoteJoin as well: https://buildkite.com/matrix-dot-org/synapse/builds/17380#9343bc23-89ea-49e7-a2cf-94bf11555fb3

The output looks similar, so they possibly stem from the same bug.

[clokep]

I wonder if this is a race on the invalidation of the cache for get_rooms_for_user_with_stream_ordering? 😕

[clokep]

I think this is fixed by #149. I'm going to close this -- we can reopen if it comes back.