Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Test case to try to reproduce missing state in sync (possibly related to MSC2716) #352

Closed

Conversation

MadLittleMods
Copy link
Contributor

@MadLittleMods MadLittleMods commented Mar 25, 2022

Test case to try to reproduce missing state in sync. Possibly a problem when using MSC2716 /batch_send

See matrix-org/synapse#12281

Dev notes

COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh TestImportHistoricalMessages/parallel/try_reproduce_missing_state_in_sync_synapse#12281
Test run
$ COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh TestImportHistoricalMessages/parallel/try_reproduce_missing_state_in_sync_synapse#12281
[+] Building 1.0s (17/17) FINISHED
 => [internal] load build definition from Dockerfile                                                                                                              0.0s
 => => transferring dockerfile: 37B                                                                                                                               0.0s
 => [internal] load .dockerignore                                                                                                                                 0.0s
 => => transferring context: 34B                                                                                                                                  0.0s
 => [internal] load metadata for docker.io/library/python:3.9-slim                                                                                                0.8s
 => [internal] load build context                                                                                                                                 0.1s
 => => transferring context: 62.95kB                                                                                                                              0.1s
 => [builder 1/8] FROM docker.io/library/python:3.9-slim@sha256:b855d669da5b39e896557608eeeb5b285399bf99e7fb321f868b59bae30da37c                                  0.0s
 => => resolve docker.io/library/python:3.9-slim@sha256:b855d669da5b39e896557608eeeb5b285399bf99e7fb321f868b59bae30da37c                                          0.0s
 => CACHED [stage-1 2/5] RUN    --mount=type=cache,target=/var/cache/apt,sharing=locked    --mount=type=cache,target=/var/lib/apt,sharing=locked   apt-get updat  0.0s
 => CACHED [builder 2/8] RUN    --mount=type=cache,target=/var/cache/apt,sharing=locked    --mount=type=cache,target=/var/lib/apt,sharing=locked  apt-get update  0.0s
 => CACHED [builder 3/8] COPY MANIFEST.in README.rst setup.py /synapse/                                                                                           0.0s
 => CACHED [builder 4/8] COPY synapse/__init__.py /synapse/synapse/__init__.py                                                                                    0.0s
 => CACHED [builder 5/8] COPY synapse/python_dependencies.py /synapse/synapse/python_dependencies.py                                                              0.0s
 => CACHED [builder 6/8] RUN --mount=type=cache,target=/root/.cache/pip   pip install --prefix="/install" --no-warn-script-location     /synapse[all]             0.0s
 => CACHED [builder 7/8] COPY synapse /synapse/synapse/                                                                                                           0.0s
 => CACHED [builder 8/8] RUN pip install --prefix="/install" --no-deps --no-warn-script-location /synapse                                                         0.0s
 => CACHED [stage-1 3/5] COPY --from=builder /install /usr/local                                                                                                  0.0s
 => CACHED [stage-1 4/5] COPY ./docker/start.py /start.py                                                                                                         0.0s
 => CACHED [stage-1 5/5] COPY ./docker/conf /conf                                                                                                                 0.0s
 => exporting to image                                                                                                                                            0.0s
 => => exporting layers                                                                                                                                           0.0s
 => => writing image sha256:e763a04731b096a7e36bba5362d8bbb4983167c52e17a138ec8a1f5ff1dcf38b                                                                      0.0s
 => => naming to docker.io/matrixdotorg/synapse                                                                                                                   0.0s

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
[+] Building 0.2s (11/11) FINISHED
 => [internal] load build definition from Synapse.Dockerfile                                                                                                      0.0s
 => => transferring dockerfile: 45B                                                                                                                               0.0s
 => [internal] load .dockerignore                                                                                                                                 0.0s
 => => transferring context: 2B                                                                                                                                   0.0s
 => [internal] load metadata for docker.io/matrixdotorg/synapse:latest                                                                                            0.0s
 => [1/6] FROM docker.io/matrixdotorg/synapse:latest                                                                                                              0.0s
 => [internal] load build context                                                                                                                                 0.0s
 => => transferring context: 367B                                                                                                                                 0.0s
 => CACHED [2/6] COPY synapse/* /conf/                                                                                                                            0.0s
 => CACHED [3/6] COPY keys/* /ca/                                                                                                                                 0.0s
 => CACHED [4/6] RUN openssl genrsa -out /conf/server.tls.key 2048                                                                                                0.0s
 => CACHED [5/6] RUN generate_signing_key -o /conf/server.signing.key                                                                                             0.0s
 => CACHED [6/6] WORKDIR /data                                                                                                                                    0.0s
 => exporting to image                                                                                                                                            0.1s
 => => exporting layers                                                                                                                                           0.0s
 => => writing image sha256:c14798d248a8f65c0ff3ea25bf5e27970e0a0fdde005c5781b817b8d7ee64d92                                                                      0.0s
 => => naming to docker.io/library/complement-synapse                                                                                                             0.0s

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
Images built; running complement
2022/03/25 13:33:52 config: &{BaseImageURI:complement-synapse BaseImageArgs:[] DebugLoggingEnabled:false AlwaysPrintServerLogs:true BestEffort:false SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] PackageNamespace:fed CACertificate:0xc001520000 CAPrivateKey:0xc000718780}
=== RUN   TestImportHistoricalMessages
    msc2716_test.go:64: Deploy times: 6.226850915s blueprints, 2.838585075s containers
    client.go:546: POST hs1/_matrix/client/r0/register => 200 OK (17.950738ms)
=== RUN   TestImportHistoricalMessages/parallel
=== RUN   TestImportHistoricalMessages/parallel/try_reproduce_missing_state_in_sync_synapse#12281
=== PAUSE TestImportHistoricalMessages/parallel/try_reproduce_missing_state_in_sync_synapse#12281
=== CONT  TestImportHistoricalMessages/parallel/try_reproduce_missing_state_in_sync_synapse#12281
=== CONT  TestImportHistoricalMessages
    client.go:546: GET hs1/_matrix/client/r0/sync => 200 OK (21.103672ms)
    client.go:546: POST hs1/_matrix/client/r0/createRoom => 200 OK (273.113314ms)
    client.go:546: GET hs1/_matrix/client/r0/sync => 200 OK (21.012674ms)
time="2022-03-25T13:34:01-05:00" level=error msg="/sync while invited (1)" firstIncrementalSyncGjson="{\"next_batch\":\"s10_2_0_1_1_1_1_4_1\",\"device_one_time_keys_count\":{\"signed_curve25519\":0},\"org.matrix.msc2732.device_unused_fallback_key_types\":[],\"device_unused_fallback_key_types\":[],\"rooms\":{\"invite\":{\"!QrZlfIDQLNLdZHqTnt:hs1\":{\"invite_state\":{\"events\":[{\"type\":\"m.room.create\",\"state_key\":\"\",\"content\":{\"room_version\":\"org.matrix.msc2716v3\",\"creator\":\"@the-bridge-user:hs1\"},\"sender\":\"@the-bridge-user:hs1\"},{\"type\":\"m.room.join_rules\",\"state_key\":\"\",\"content\":{\"join_rule\":\"public\"},\"sender\":\"@the-bridge-user:hs1\"},{\"type\":\"m.room.name\",\"state_key\":\"\",\"content\":{\"name\":\"the hangout spot\"},\"sender\":\"@the-bridge-user:hs1\"},{\"type\":\"m.room.member\",\"state_key\":\"@the-bridge-user:hs1\",\"content\":{\"membership\":\"join\"},\"sender\":\"@the-bridge-user:hs1\"},{\"type\":\"m.room.member\",\"sender\":\"@the-bridge-user:hs1\",\"content\":{\"membership\":\"invite\",\"displayname\":\"Alice\"},\"state_key\":\"@alice:hs1\",\"origin_server_ts\":1648233241580,\"unsigned\":{\"age\":35},\"event_id\":\"$37mA9o8VZrBFZbm_T8feqpgOPAOs2YHdlD1uKke082E\"}]}}}}}"
    client.go:546: POST hs1/_matrix/client/r0/join/!QrZlfIDQLNLdZHqTnt:hs1 => 200 OK (22.208548ms)
    client.go:546: PUT hs1/_matrix/client/r0/rooms/!QrZlfIDQLNLdZHqTnt:hs1/send/m.room.message/sendLiveEvent-txn-0 => 200 OK (32.634418ms)
    client.go:546: POST hs1/_matrix/client/unstable/org.matrix.msc2716/rooms/!QrZlfIDQLNLdZHqTnt:hs1/batch_send => 200 OK (93.009782ms)
    client.go:546: GET hs1/_matrix/client/r0/sync => 200 OK (16.919721ms)
time="2022-03-25T13:34:01-05:00" level=error msg="/sync after join (2)" topLevelSyncJSON="{\"next_batch\":\"s12_4_0_1_1_1_1_4_1\",\"presence\":{\"events\":[{\"type\":\"m.presence\",\"sender\":\"@the-bridge-user:hs1\",\"content\":{\"presence\":\"offline\",\"last_active_ago\":103}}]},\"device_lists\":{\"changed\":[\"@alice:hs1\"]},\"device_one_time_keys_count\":{\"signed_curve25519\":0},\"org.matrix.msc2732.device_unused_fallback_key_types\":[],\"device_unused_fallback_key_types\":[],\"rooms\":{\"join\":{\"!QrZlfIDQLNLdZHqTnt:hs1\":{\"timeline\":{\"events\":[{\"type\":\"m.room.member\",\"sender\":\"@alice:hs1\",\"content\":{\"membership\":\"join\",\"displayname\":\"Alice\"},\"state_key\":\"@alice:hs1\",\"origin_server_ts\":1648233241622,\"unsigned\":{\"replaces_state\":\"$37mA9o8VZrBFZbm_T8feqpgOPAOs2YHdlD1uKke082E\",\"prev_content\":{\"membership\":\"invite\",\"displayname\":\"Alice\"},\"prev_sender\":\"@the-bridge-user:hs1\",\"age\":158},\"event_id\":\"$tz6O9OtboMOgeCkLI3q3dcvJPIv92F8VCQCSy4-ECFM\"},{\"type\":\"m.room.message\",\"sender\":\"@the-bridge-user:hs1\",\"content\":{\"body\":\"foo\",\"msgtype\":\"m.text\"},\"origin_server_ts\":1648233241656,\"unsigned\":{\"age\":124},\"event_id\":\"$43djMtYXP4xL1vr3ko7_cqaLgcVmIgN3FKBp8PEtmb8\"}],\"prev_batch\":\"s10_4_0_1_1_1_1_4_1\",\"limited\":false},\"state\":{\"events\":[]},\"account_data\":{\"events\":[]},\"ephemeral\":{\"events\":[]},\"unread_notifications\":{\"notification_count\":1,\"highlight_count\":0},\"summary\":{},\"org.matrix.msc2654.unread_count\":1}}}}"
    client.go:546: GET hs1/_matrix/client/r0/sync => 200 OK (1.004040086s)
time="2022-03-25T13:34:02-05:00" level=error msg="/sync after join (2)" topLevelSyncJSON="{\"next_batch\":\"s12_4_0_1_1_1_1_4_1\",\"device_one_time_keys_count\":{\"signed_curve25519\":0},\"org.matrix.msc2732.device_unused_fallback_key_types\":[],\"device_unused_fallback_key_types\":[]}"
    client.go:546: GET hs1/_matrix/client/r0/sync => 200 OK (1.005300739s)
time="2022-03-25T13:34:03-05:00" level=error msg="/sync after join (2)" topLevelSyncJSON="{\"next_batch\":\"s12_4_0_1_1_1_1_4_1\",\"device_one_time_keys_count\":{\"signed_curve25519\":0},\"org.matrix.msc2732.device_unused_fallback_key_types\":[],\"device_unused_fallback_key_types\":[]}"
    client.go:546: GET hs1/_matrix/client/r0/sync => 200 OK (1.007393428s)
time="2022-03-25T13:34:04-05:00" level=error msg="/sync after join (2)" topLevelSyncJSON="{\"next_batch\":\"s12_4_0_1_1_1_1_4_1\",\"device_one_time_keys_count\":{\"signed_curve25519\":0},\"org.matrix.msc2732.device_unused_fallback_key_types\":[],\"device_unused_fallback_key_types\":[]}"
2022/03/25 13:34:04 ============================================


2022/03/25 13:34:04 52ffe8b664a424d159290c63ee32dbeccaae8f34c9d49e5d812201577a853da4 : Server logs:
Signature ok
subject=CN = hs2
Getting CA Private Key
2022-03-25 18:34:00,612 - root - 352 - WARNING - main - ***** STARTING SERVER *****
2022-03-25 18:34:00,612 - root - 353 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.55.2
2022-03-25 18:34:00,612 - root - 358 - INFO - main - Server hostname: hs2
2022-03-25 18:34:00,613 - root - 359 - INFO - main - Instance name: master
2022-03-25 18:34:00,613 - synapse.app.homeserver - 362 - INFO - main - Setting up server
2022-03-25 18:34:00,613 - synapse.server - 315 - INFO - main - Setting up.
2022-03-25 18:34:00,617 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2022-03-25 18:34:00,617 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2022-03-25 18:34:00,618 - synapse.storage.prepare_database - 116 - INFO - main - ['main', 'state']: Checking existing schema version
2022-03-25 18:34:00,621 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Existing schema is 68 (+7 deltas)
2022-03-25 18:34:00,621 - synapse.storage.databases.main - 355 - INFO - main - Checking database for consistency with configuration...
2022-03-25 18:34:00,621 - synapse.storage.prepare_database - 412 - INFO - main - Applying schema deltas for v68
2022-03-25 18:34:00,621 - synapse.storage.prepare_database - 547 - INFO - main - Schema now up to date
2022-03-25 18:34:00,623 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database
2022-03-25 18:34:00,623 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 2
2022-03-25 18:34:00,624 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1
2022-03-25 18:34:00,624 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1
2022-03-25 18:34:00,624 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1
2022-03-25 18:34:00,624 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1
2022-03-25 18:34:00,624 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for local_group_updates(stream_id): 1
2022-03-25 18:34:00,624 - synapse.config.appservice - 59 - WARNING - main - Expected None to be a list of AS config files.
2022-03-25 18:34:00,625 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1
2022-03-25 18:34:00,625 - synapse.storage.databases.main.event_push_actions - 608 - INFO - main - Searching for stream ordering 1 month ago
2022-03-25 18:34:00,625 - synapse.storage.databases.main.event_push_actions - 612 - INFO - main - Found stream ordering 1 month ago: it's 0
2022-03-25 18:34:00,625 - synapse.storage.databases.main.event_push_actions - 615 - INFO - main - Searching for stream ordering 1 day ago
2022-03-25 18:34:00,625 - synapse.storage.databases.main.event_push_actions - 619 - INFO - main - Found stream ordering 1 day ago: it's 0
2022-03-25 18:34:00,626 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1
2022-03-25 18:34:00,626 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1
2022-03-25 18:34:00,626 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1
2022-03-25 18:34:00,627 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1
2022-03-25 18:34:00,627 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1
2022-03-25 18:34:00,628 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1
2022-03-25 18:34:00,628 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1
2022-03-25 18:34:00,628 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1
2022-03-25 18:34:00,628 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1
2022-03-25 18:34:00,629 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1
2022-03-25 18:34:00,629 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1
2022-03-25 18:34:00,629 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 2
2022-03-25 18:34:00,630 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
2022-03-25 18:34:00,630 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1
2022-03-25 18:34:00,630 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2022-03-25 18:34:00,631 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared
2022-03-25 18:34:00,631 - synapse.server - 318 - INFO - main - Finished setting up.
2022-03-25 18:34:00,638 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False
2022-03-25 18:34:00,639 - synapse.federation.federation_server - 1295 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
2022-03-25 18:34:00,639 - synapse.federation.federation_server - 1315 - INFO - main - Registering federation query handler for 'profile'
2022-03-25 18:34:00,640 - synapse.federation.federation_server - 1295 - INFO - main - Registering federation EDU handler for 'm.presence'
2022-03-25 18:34:00,641 - synapse.federation.federation_server - 1295 - INFO - main - Registering federation EDU handler for 'm.typing'
2022-03-25 18:34:00,641 - synapse.federation.federation_server - 1315 - INFO - main - Registering federation query handler for 'directory'
2022-03-25 18:34:00,641 - twisted - 283 - INFO - main - Redirected stdout/stderr to logs
2022-03-25 18:34:00,642 - synapse.app.homeserver - 156 - INFO - sentinel - Running
2022-03-25 18:34:00,643 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576
2022-03-25 18:34:00,644 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter
2022-03-25 18:34:00,646 - synapse.config.tls - 260 - INFO - sentinel - Loading TLS key from /conf/server.tls.key
2022-03-25 18:34:00,646 - synapse.config.tls - 247 - INFO - sentinel - Loading TLS certificate from /conf/server.tls.crt
2022-03-25 18:34:00,648 - synapse.util.caches.lrucache - 164 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2022-03-25 18:34:00,657 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7f9653f31f40> to path b'/health'
2022-03-25 18:34:00,658 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7f9653f360a0> to path b'/_matrix/federation'
2022-03-25 18:34:00,658 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f9653f361c0> to path b'/_matrix/media/r0'
2022-03-25 18:34:00,658 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f9653f361c0> to path b'/_matrix/media/v3'
2022-03-25 18:34:00,658 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f9653f361c0> to path b'/_matrix/media/v1'
2022-03-25 18:34:00,658 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7f9650ecd970> to path b'/_matrix/key/v2'
2022-03-25 18:34:00,658 - twisted - 283 - INFO - sentinel - SynapseSite (TLS) starting on 8448
2022-03-25 18:34:00,659 - synapse.app.homeserver - 167 - INFO - sentinel - Synapse now listening on TCP port 8448 (TLS)
2022-03-25 18:34:00,670 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
2022-03-25 18:34:00,670 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
2022-03-25 18:34:00,670 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
2022-03-25 18:34:00,670 - synapse.federation.federation_server - 1315 - INFO - sentinel - Registering federation query handler for 'client_keys'
2022-03-25 18:34:00,671 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7f9650ecdeb0> to path b'/health'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7f9650ed7790> to path b'/_matrix/client'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f9650e9fac0> to path b'/.well-known'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7f9650e9fca0> to path b'/_synapse/admin'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7f9650eaf610> to path b'/_synapse/client/pick_idp'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f9650eaf4f0> to path b'/_synapse/client/pick_username'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7f9650eaf910> to path b'/_synapse/client/new_user_consent'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7f9650eaf940> to path b'/_synapse/client/sso_register'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f9653f361c0> to path b'/_matrix/media/r0'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f9653f361c0> to path b'/_matrix/media/v3'
2022-03-25 18:34:00,673 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f9653f361c0> to path b'/_matrix/media/v1'
2022-03-25 18:34:00,674 - twisted - 283 - INFO - sentinel - SynapseSite starting on 8008
2022-03-25 18:34:00,674 - synapse.app.homeserver - 176 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-03-25 18:34:00,713 - synapse.storage.background_updates - 277 - INFO - background_updates-0 - Starting background schema updates
2022-03-25 18:34:00,714 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-03-25 18:34:00,715 - synapse.push.pusherpool - 314 - INFO - start_pushers-0 - Started pushers
2022-03-25 18:34:01,255 - synapse.access.http.8008 - 427 - INFO - GET-1 - ::ffff:192.168.224.1 - 8008 - {None} Processed request: 0.001sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 557B 200 "GET /_matrix/client/versions HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,719 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'add_rooms_room_version_column'
2022-03-25 18:34:01,722 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'add_rooms_room_version_column'. Processed 100 items in 2ms. (total_rate=50.0/ms, current_rate=50.0/ms, total_updated=100, batch_size=100)
2022-03-25 18:34:02,725 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'current_state_events_membership'
2022-03-25 18:34:02,731 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'current_state_events_membership'. Processed 0 items in 5ms. (total_rate=None/ms, current_rate=None/ms, total_updated=0, batch_size=100)
2022-03-25 18:34:03,733 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'
2022-03-25 18:34:03,741 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 100 items in 6ms. (total_rate=16.666666666666668/ms, current_rate=16.666666666666664/ms, total_updated=100, batch_size=100)
2022-03-25 18:34:04,743 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'devices_last_seen'
2022-03-25 18:34:04,750 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'devices_last_seen'. Processed 0 items in 5ms. (total_rate=None/ms, current_rate=None/ms, total_updated=0, batch_size=100)
2022/03/25 13:34:04 ============== 52ffe8b664a424d159290c63ee32dbeccaae8f34c9d49e5d812201577a853da4 : END LOGS ==============


2022/03/25 13:34:04 ============================================


2022/03/25 13:34:04 48ff66730269339f7926e2ccd7aca1698bbafc2a4a7c22601a8b7096ae32fe40 : Server logs:
Signature ok
subject=CN = hs1
Getting CA Private Key
2022-03-25 18:34:00,643 - root - 352 - WARNING - main - ***** STARTING SERVER *****
2022-03-25 18:34:00,643 - root - 353 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.55.2
2022-03-25 18:34:00,643 - root - 358 - INFO - main - Server hostname: hs1
2022-03-25 18:34:00,643 - root - 359 - INFO - main - Instance name: master
2022-03-25 18:34:00,643 - synapse.app.homeserver - 362 - INFO - main - Setting up server
2022-03-25 18:34:00,643 - synapse.server - 315 - INFO - main - Setting up.
2022-03-25 18:34:00,648 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2022-03-25 18:34:00,648 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2022-03-25 18:34:00,648 - synapse.storage.prepare_database - 116 - INFO - main - ['main', 'state']: Checking existing schema version
2022-03-25 18:34:00,651 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Existing schema is 68 (+7 deltas)
2022-03-25 18:34:00,651 - synapse.storage.databases.main - 355 - INFO - main - Checking database for consistency with configuration...
2022-03-25 18:34:00,651 - synapse.storage.prepare_database - 412 - INFO - main - Applying schema deltas for v68
2022-03-25 18:34:00,652 - synapse.storage.prepare_database - 547 - INFO - main - Schema now up to date
2022-03-25 18:34:00,653 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database
2022-03-25 18:34:00,654 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 3
2022-03-25 18:34:00,654 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1
2022-03-25 18:34:00,654 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1
2022-03-25 18:34:00,654 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1
2022-03-25 18:34:00,654 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1
2022-03-25 18:34:00,654 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for local_group_updates(stream_id): 1
2022-03-25 18:34:00,656 - synapse.config.appservice - 90 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://localhost:9000', 'hs_token': '<redacted>', 'sender': '@the-bridge-user:hs1', 'server_name': 'hs1', 'namespaces': {'users': [Namespace(exclusive=False, group_id=None, regex=re.compile('.*'))], 'aliases': [], 'rooms': []}, 'id': 'my_as_id', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2022-03-25 18:34:00,656 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1
2022-03-25 18:34:00,657 - synapse.storage.databases.main.event_push_actions - 608 - INFO - main - Searching for stream ordering 1 month ago
2022-03-25 18:34:00,657 - synapse.storage.databases.main.event_push_actions - 612 - INFO - main - Found stream ordering 1 month ago: it's 0
2022-03-25 18:34:00,657 - synapse.storage.databases.main.event_push_actions - 615 - INFO - main - Searching for stream ordering 1 day ago
2022-03-25 18:34:00,657 - synapse.storage.databases.main.event_push_actions - 619 - INFO - main - Found stream ordering 1 day ago: it's 0
2022-03-25 18:34:00,657 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1
2022-03-25 18:34:00,658 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1
2022-03-25 18:34:00,658 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1
2022-03-25 18:34:00,658 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1
2022-03-25 18:34:00,659 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1
2022-03-25 18:34:00,659 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1
2022-03-25 18:34:00,660 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1
2022-03-25 18:34:00,660 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1
2022-03-25 18:34:00,660 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1
2022-03-25 18:34:00,660 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1
2022-03-25 18:34:00,661 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1
2022-03-25 18:34:00,661 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 3
2022-03-25 18:34:00,661 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
2022-03-25 18:34:00,661 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1
2022-03-25 18:34:00,662 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2022-03-25 18:34:00,662 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared
2022-03-25 18:34:00,663 - synapse.server - 318 - INFO - main - Finished setting up.
2022-03-25 18:34:00,669 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False
2022-03-25 18:34:00,671 - synapse.federation.federation_server - 1295 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
2022-03-25 18:34:00,671 - synapse.federation.federation_server - 1315 - INFO - main - Registering federation query handler for 'profile'
2022-03-25 18:34:00,672 - synapse.federation.federation_server - 1295 - INFO - main - Registering federation EDU handler for 'm.presence'
2022-03-25 18:34:00,673 - synapse.federation.federation_server - 1295 - INFO - main - Registering federation EDU handler for 'm.typing'
2022-03-25 18:34:00,673 - synapse.federation.federation_server - 1315 - INFO - main - Registering federation query handler for 'directory'
2022-03-25 18:34:00,674 - twisted - 283 - INFO - main - Redirected stdout/stderr to logs
2022-03-25 18:34:00,674 - synapse.app.homeserver - 156 - INFO - sentinel - Running
2022-03-25 18:34:00,676 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576
2022-03-25 18:34:00,676 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter
2022-03-25 18:34:00,678 - synapse.config.tls - 260 - INFO - sentinel - Loading TLS key from /conf/server.tls.key
2022-03-25 18:34:00,678 - synapse.config.tls - 247 - INFO - sentinel - Loading TLS certificate from /conf/server.tls.crt
2022-03-25 18:34:00,679 - synapse.util.caches.lrucache - 164 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2022-03-25 18:34:00,692 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7ff5a5c4ebb0> to path b'/health'
2022-03-25 18:34:00,692 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7ff5a5c4ecd0> to path b'/_matrix/federation'
2022-03-25 18:34:00,693 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7ff5a5c4ee80> to path b'/_matrix/media/r0'
2022-03-25 18:34:00,693 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7ff5a5c4ee80> to path b'/_matrix/media/v3'
2022-03-25 18:34:00,693 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7ff5a5c4ee80> to path b'/_matrix/media/v1'
2022-03-25 18:34:00,693 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7ff5a43f80d0> to path b'/_matrix/key/v2'
2022-03-25 18:34:00,694 - twisted - 283 - INFO - sentinel - SynapseSite (TLS) starting on 8448
2022-03-25 18:34:00,694 - synapse.app.homeserver - 167 - INFO - sentinel - Synapse now listening on TCP port 8448 (TLS)
2022-03-25 18:34:00,709 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
2022-03-25 18:34:00,710 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
2022-03-25 18:34:00,710 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
2022-03-25 18:34:00,710 - synapse.federation.federation_server - 1315 - INFO - sentinel - Registering federation query handler for 'client_keys'
2022-03-25 18:34:00,710 - synapse.federation.federation_server - 1295 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7ff5a43f8670> to path b'/health'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7ff5a43f8f40> to path b'/_matrix/client'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7ff5a43c48b0> to path b'/.well-known'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7ff5a43c4a90> to path b'/_synapse/admin'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7ff5a43d7400> to path b'/_synapse/client/pick_idp'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7ff5a43d72e0> to path b'/_synapse/client/pick_username'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7ff5a43d7700> to path b'/_synapse/client/new_user_consent'
2022-03-25 18:34:00,713 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7ff5a43d7730> to path b'/_synapse/client/sso_register'
2022-03-25 18:34:00,714 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static'
2022-03-25 18:34:00,714 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7ff5a5c4ee80> to path b'/_matrix/media/r0'
2022-03-25 18:34:00,714 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7ff5a5c4ee80> to path b'/_matrix/media/v3'
2022-03-25 18:34:00,714 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7ff5a5c4ee80> to path b'/_matrix/media/v1'
2022-03-25 18:34:00,714 - twisted - 283 - INFO - sentinel - SynapseSite starting on 8008
2022-03-25 18:34:00,714 - synapse.app.homeserver - 176 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-03-25 18:34:00,756 - synapse.storage.background_updates - 277 - INFO - background_updates-0 - Starting background schema updates
2022-03-25 18:34:00,756 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-03-25 18:34:00,758 - synapse.push.pusherpool - 314 - INFO - start_pushers-0 - Started pushers
2022-03-25 18:34:01,281 - synapse.access.http.8008 - 427 - INFO - GET-1 - ::ffff:192.168.224.1 - 8008 - {None} Processed request: 0.001sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 557B 200 "GET /_matrix/client/versions HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,296 - synapse.handlers.auth - 974 - INFO - POST-2 - Logging in user @maria:hs1 on device JUHWZDYWDP
2022-03-25 18:34:01,299 - synapse.access.http.8008 - 427 - INFO - POST-2 - ::ffff:192.168.224.1 - 8008 - {@the-bridge-user:hs1} Processed request: 0.015sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.009sec/6) 126B 200 "POST /_matrix/client/r0/register HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,320 - synapse.access.http.8008 - 427 - INFO - GET-3 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 0.017sec/0.001sec (0.004sec, 0.001sec) (0.003sec/0.004sec/16) 3901B 200 "GET /_matrix/client/r0/sync?timeout=1000 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,351 - synapse.appservice.scheduler - 109 - INFO - as_scheduler-0 - Starting appservice scheduler
2022-03-25 18:34:01,374 - synapse.handlers.message - 601 - INFO - POST-4 - Failed to get profile information for @the-bridge-user:hs1: 404: Profile was not found
2022-03-25 18:34:01,593 - synapse.access.http.8008 - 427 - INFO - POST-4 - ::ffff:192.168.224.1 - 8008 - {@the-bridge-user:hs1} Processed request: 0.270sec/0.001sec (0.031sec, 0.010sec) (0.112sec/0.038sec/63) 37B 200 "POST /_matrix/client/r0/createRoom HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,613 - synapse.handlers.sync - 707 - INFO - GET-5 - Failed to find any events in room !QrZlfIDQLNLdZHqTnt:hs1 at RoomStreamToken(topological=None, stream=1, instance_map=frozendict.frozendict({}))
2022-03-25 18:34:01,615 - synapse.access.http.8008 - 427 - INFO - GET-5 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 0.017sec/0.000sec (0.002sec, 0.001sec) (0.010sec/0.003sec/6) 1008B 200 "GET /_matrix/client/r0/sync?since=s1_2_0_1_1_1_1_4_1&timeout=1000 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,618 - synapse.http.servlet - 663 - WARNING - POST-6 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0) (b'')
2022-03-25 18:34:01,636 - synapse.access.http.8008 - 427 - INFO - POST-6 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 0.018sec/0.001sec (0.005sec, 0.000sec) (0.003sec/0.003sec/13) 37B 200 "POST /_matrix/client/r0/join/%21QrZlfIDQLNLdZHqTnt:hs1 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,670 - synapse.access.http.8008 - 427 - INFO - PUT-7 - ::ffff:192.168.224.1 - 8008 - {@the-bridge-user:hs1} Processed request: 0.028sec/0.001sec (0.003sec, 0.000sec) (0.013sec/0.003sec/6) 59B 200 "PUT /_matrix/client/r0/rooms/%21QrZlfIDQLNLdZHqTnt:hs1/send/m.room.message/sendLiveEvent-txn-0 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,677 - synapse.logging.context - 81 - WARNING - PUT-7 - Re-starting finished log context PUT-7
2022-03-25 18:34:01,677 - synapse.logging.context - 81 - WARNING - PUT-7 - Re-starting finished log context PUT-7
2022-03-25 18:34:01,685 - synapse.logging.context - 81 - WARNING - PUT-7 - Re-starting finished log context PUT-7
2022-03-25 18:34:01,743 - synapse.logging.context - 81 - WARNING - POST-8 - Re-starting finished log context POST-8
2022-03-25 18:34:01,743 - synapse.logging.context - 81 - WARNING - POST-8 - Re-starting finished log context POST-8
2022-03-25 18:34:01,751 - synapse.logging.context - 81 - WARNING - POST-8 - Re-starting finished log context POST-8
2022-03-25 18:34:01,762 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'devices_last_seen'
2022-03-25 18:34:01,763 - synapse.access.http.8008 - 427 - INFO - POST-8 - ::ffff:192.168.224.1 - 8008 - {@the-bridge-user:hs1} Processed request: 0.089sec/0.001sec (0.014sec, 0.002sec) (0.019sec/0.020sec/26) 455B 200 "POST /_matrix/client/unstable/org.matrix.msc2716/rooms/%21QrZlfIDQLNLdZHqTnt:hs1/batch_send?prev_event_id=%2443djMtYXP4xL1vr3ko7_cqaLgcVmIgN3FKBp8PEtmb8 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,771 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'devices_last_seen'. Processed 0 items in 6ms. (total_rate=None/ms, current_rate=None/ms, total_updated=0, batch_size=100)
2022-03-25 18:34:01,781 - synapse.access.http.8008 - 427 - INFO - GET-9 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 0.013sec/0.000sec (0.004sec, 0.000sec) (0.004sec/0.002sec/10) 1293B 200 "GET /_matrix/client/r0/sync?since=s10_2_0_1_1_1_1_4_1&timeout=1000 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:01,969 - synapse.http.client - 455 - INFO - as-sender-my_as_id-0 - Error sending request to  PUT http://localhost:9000/transactions/1?access_token=<redacted>: ConnectError Cannot assign requested address
2022-03-25 18:34:01,970 - synapse.appservice.api - 305 - WARNING - as-sender-my_as_id-0 - push_bulk to http://localhost:9000/transactions/1 threw exception(ConnectError) An error occurred while connecting: 99: Cannot assign requested address. args=('Cannot assign requested address',)
2022-03-25 18:34:01,975 - synapse.appservice.scheduler - 383 - INFO - as-sender-my_as_id-0 - Starting recoverer for AS ID my_as_id
2022-03-25 18:34:01,976 - synapse.appservice.scheduler - 432 - INFO - as-sender-my_as_id-0 - Scheduling retries on my_as_id in 2.000000s
2022-03-25 18:34:01,976 - synapse.appservice.scheduler - 390 - INFO - as-sender-my_as_id-0 - Now 1 active recoverers
2022-03-25 18:34:02,775 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'event_store_labels'
2022-03-25 18:34:02,782 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'event_store_labels'. Processed 18 items in 5ms. (total_rate=3.6/ms, current_rate=3.6/ms, total_updated=18, batch_size=100)
2022-03-25 18:34:02,785 - synapse.access.http.8008 - 427 - INFO - GET-10 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 1.002sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/1) 184B 200 "GET /_matrix/client/r0/sync?since=s12_4_0_1_1_1_1_4_1&timeout=1000 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:03,784 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'event_store_labels'
2022-03-25 18:34:03,792 - synapse.access.http.8008 - 427 - INFO - GET-12 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 1.002sec/0.001sec (0.003sec, 0.000sec) (0.000sec/0.000sec/1) 184B 200 "GET /_matrix/client/r0/sync?since=s12_4_0_1_1_1_1_4_1&timeout=1000 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:03,794 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'event_store_labels'. Processed 0 items in 8ms. (total_rate=1.3846153846153846/ms, current_rate=1.296/ms, total_updated=18, batch_size=360)
2022-03-25 18:34:03,978 - synapse.appservice.scheduler - 442 - INFO - as-recoverer-my_as_id-0 - Starting retries on my_as_id
2022-03-25 18:34:03,980 - synapse.appservice.scheduler - 451 - INFO - as-recoverer-my_as_id-0 - Retrying transaction 1 for AS ID my_as_id
2022-03-25 18:34:04,583 - synapse.http.client - 455 - INFO - as-recoverer-my_as_id-0 - Error sending request to  PUT http://localhost:9000/transactions/1?access_token=<redacted>: ConnectError Cannot assign requested address
2022-03-25 18:34:04,583 - synapse.appservice.api - 305 - WARNING - as-recoverer-my_as_id-0 - push_bulk to http://localhost:9000/transactions/1 threw exception(ConnectError) An error occurred while connecting: 99: Cannot assign requested address. args=('Cannot assign requested address',)
2022-03-25 18:34:04,584 - synapse.appservice.scheduler - 432 - INFO - as-recoverer-my_as_id-0 - Scheduling retries on my_as_id in 4.000000s
2022-03-25 18:34:04,798 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'insert_room_retention'
2022-03-25 18:34:04,800 - synapse.access.http.8008 - 427 - INFO - GET-14 - ::ffff:192.168.224.1 - 8008 - {@alice:hs1} Processed request: 1.004sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.000sec/1) 184B 200 "GET /_matrix/client/r0/sync?since=s12_4_0_1_1_1_1_4_1&timeout=1000 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-25 18:34:04,808 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'insert_room_retention'. Processed 100 items in 6ms. (total_rate=16.666666666666668/ms, current_rate=16.666666666666664/ms, total_updated=100, batch_size=100)
2022-03-25 18:34:04,809 - synapse.storage.background_updates - 379 - INFO - background_updates-0 - Not starting on bg update populate_stats_process_users until populate_stats_process_rooms is done
2022/03/25 13:34:04 ============== 48ff66730269339f7926e2ccd7aca1698bbafc2a4a7c22601a8b7096ae32fe40 : END LOGS ==============


--- PASS: TestImportHistoricalMessages (12.96s)
    --- PASS: TestImportHistoricalMessages/parallel (0.00s)
        --- PASS: TestImportHistoricalMessages/parallel/try_reproduce_missing_state_in_sync_synapse#12281 (3.50s)
PASS
ok  	github.com/matrix-org/complement/tests	15.713s
2022/03/25 13:33:50 config: &{BaseImageURI:complement-synapse BaseImageArgs:[] DebugLoggingEnabled:false AlwaysPrintServerLogs:true BestEffort:false SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] PackageNamespace:csapi CACertificate:0xc00024eb00 CAPrivateKey:0xc000020f00}
testing: warning: no tests to run
PASS
ok  	github.com/matrix-org/complement/tests/csapi	0.842s [no tests to run]

First sync while invited (1):

sync (1)
{
  "next_batch": "s10_2_0_1_1_1_1_4_1",
  "device_one_time_keys_count": {
    "signed_curve25519": 0
  },
  "org.matrix.msc2732.device_unused_fallback_key_types": [],
  "device_unused_fallback_key_types": [],
  "rooms": {
    "invite": {
      "!QrZlfIDQLNLdZHqTnt:hs1": {
        "invite_state": {
          "events": [
            {
              "type": "m.room.create",
              "state_key": "",
              "content": {
                "room_version": "org.matrix.msc2716v3",
                "creator": "@the-bridge-user:hs1"
              },
              "sender": "@the-bridge-user:hs1"
            },
            {
              "type": "m.room.join_rules",
              "state_key": "",
              "content": {
                "join_rule": "public"
              },
              "sender": "@the-bridge-user:hs1"
            },
            {
              "type": "m.room.name",
              "state_key": "",
              "content": {
                "name": "the hangout spot"
              },
              "sender": "@the-bridge-user:hs1"
            },
            {
              "type": "m.room.member",
              "state_key": "@the-bridge-user:hs1",
              "content": {
                "membership": "join"
              },
              "sender": "@the-bridge-user:hs1"
            },
            {
              "type": "m.room.member",
              "sender": "@the-bridge-user:hs1",
              "content": {
                "membership": "invite",
                "displayname": "Alice"
              },
              "state_key": "@alice:hs1",
              "origin_server_ts": 1648233241580,
              "unsigned": {
                "age": 35
              },
              "event_id": "$37mA9o8VZrBFZbm_T8feqpgOPAOs2YHdlD1uKke082E"
            }
          ]
        }
      }
    }
  }
}

Second sync after join (2):

sync (2)
{
  "next_batch": "s12_4_0_1_1_1_1_4_1",
  "presence": {
    "events": [
      {
        "type": "m.presence",
        "sender": "@the-bridge-user:hs1",
        "content": {
          "presence": "offline",
          "last_active_ago": 103
        }
      }
    ]
  },
  "device_lists": {
    "changed": [
      "@alice:hs1"
    ]
  },
  "device_one_time_keys_count": {
    "signed_curve25519": 0
  },
  "org.matrix.msc2732.device_unused_fallback_key_types": [],
  "device_unused_fallback_key_types": [],
  "rooms": {
    "join": {
      "!QrZlfIDQLNLdZHqTnt:hs1": {
        "timeline": {
          "events": [
            {
              "type": "m.room.member",
              "sender": "@alice:hs1",
              "content": {
                "membership": "join",
                "displayname": "Alice"
              },
              "state_key": "@alice:hs1",
              "origin_server_ts": 1648233241622,
              "unsigned": {
                "replaces_state": "$37mA9o8VZrBFZbm_T8feqpgOPAOs2YHdlD1uKke082E",
                "prev_content": {
                  "membership": "invite",
                  "displayname": "Alice"
                },
                "prev_sender": "@the-bridge-user:hs1",
                "age": 158
              },
              "event_id": "$tz6O9OtboMOgeCkLI3q3dcvJPIv92F8VCQCSy4-ECFM"
            },
            {
              "type": "m.room.message",
              "sender": "@the-bridge-user:hs1",
              "content": {
                "body": "foo",
                "msgtype": "m.text"
              },
              "origin_server_ts": 1648233241656,
              "unsigned": {
                "age": 124
              },
              "event_id": "$43djMtYXP4xL1vr3ko7_cqaLgcVmIgN3FKBp8PEtmb8"
            }
          ],
          "prev_batch": "s10_4_0_1_1_1_1_4_1",
          "limited": false
        },
        "state": {
          "events": []
        },
        "account_data": {
          "events": []
        },
        "ephemeral": {
          "events": []
        },
        "unread_notifications": {
          "notification_count": 1,
          "highlight_count": 0
        },
        "summary": {},
        "org.matrix.msc2654.unread_count": 1
      }
    }
  }
}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant