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.

Sign up for GitHub

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

Jump to bottom

TestUnrejectRejectedEvents and TestInviteFromIgnoredUsersDoesNotAppearInSync with synapse seem to be flaky #349

Closed
deepbluev7 opened this issue Mar 23, 2022 · 4 comments
Closed

TestUnrejectRejectedEvents and TestInviteFromIgnoredUsersDoesNotAppearInSync with synapse seem to be flaky #349

deepbluev7 opened this issue Mar 23, 2022 · 4 comments

Comments

@deepbluev7
Copy link

deepbluev7 commented Mar 23, 2022 •
edited
Loading

Describe the bug

TestUnrejectRejectedEvents and TestInviteFromIgnoredUsersDoesNotAppearInSync failed randomly in our CI pipeline. I'm not sure if that is because of synapse or complement, but rerunning the test fixed it.

To Reproduce

Hard to reproduce intentionally, but here is a link to the failing job: https://gitlab.com/famedly/company/backend/services/synapse/-/jobs/2241320546

Long logs 

=== FAIL: tests TestUnrejectRejectedEvents (70.81s)
    federation_unreject_rejected_test.go:20: Deploy times: 3.066433ms blueprints, 2.83576249s containers
    client.go:546: GET hs1/_matrix/client/r0/capabilities => 200 OK (2.247913188s)
    server.go:161: Creating room !0:host.docker.internal:43483 with version 9
    client.go:546: POST hs1/_matrix/client/r0/join/!0:host.docker.internal:43483 => 200 OK (3.001146529s)
    client.go:544: GET hs1/_matrix/client/r0/sync => error: net/http: request canceled (30.000360553s)
    federation_unreject_rejected_test.go:39: CSAPI.DoFunc response returned error: Get "http://localhost:49276/_matrix/client/r0/sync?timeout=1000": net/http: request canceled (Client.Timeout exceeded while awaiting headers)
2022/03/23 12:40:18 ============================================
2022/03/23 12:40:18 2dcc0509705e63a2e79e66e71180f8af1fe5e1aee1ccaa96faeaf3d4e6596d7a : Server logs:
Signature ok
subject=CN = hs1
Getting CA Private Key
2022-03-23 16:39:25,780 - root - 352 - WARNING - main - ***** STARTING SERVER *****
2022-03-23 16:39:25,780 - root - 353 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.55.0
2022-03-23 16:39:25,781 - root - 358 - INFO - main - Server hostname: hs1
2022-03-23 16:39:25,781 - root - 359 - INFO - main - Instance name: master
2022-03-23 16:39:25,781 - synapse.app.homeserver - 359 - INFO - main - Setting up server
2022-03-23 16:39:25,781 - synapse.server - 314 - INFO - main - Setting up.
2022-03-23 16:39:25,800 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2022-03-23 16:39:25,801 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2022-03-23 16:39:25,801 - synapse.storage.prepare_database - 116 - INFO - main - ['main', 'state']: Checking existing schema version
2022-03-23 16:39:25,817 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Existing schema is 68 (+7 deltas)
2022-03-23 16:39:25,818 - synapse.storage.databases.main - 355 - INFO - main - Checking database for consistency with configuration...
2022-03-23 16:39:25,818 - synapse.storage.prepare_database - 412 - INFO - main - Applying schema deltas for v68
2022-03-23 16:39:25,819 - synapse.storage.prepare_database - 547 - INFO - main - Schema now up to date
2022-03-23 16:39:25,834 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database
2022-03-23 16:39:25,835 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 2
2022-03-23 16:39:25,835 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1
2022-03-23 16:39:25,835 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1
2022-03-23 16:39:25,836 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1
2022-03-23 16:39:25,836 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1
2022-03-23 16:39:25,836 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for local_group_updates(stream_id): 1
2022-03-23 16:39:25,837 - synapse.config.appservice - 59 - WARNING - main - Expected None to be a list of AS config files.
2022-03-23 16:39:25,837 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1
2022-03-23 16:39:25,838 - synapse.storage.databases.main.event_push_actions - 608 - INFO - main - Searching for stream ordering 1 month ago
2022-03-23 16:39:25,838 - synapse.storage.databases.main.event_push_actions - 612 - INFO - main - Found stream ordering 1 month ago: it's 0
2022-03-23 16:39:25,838 - synapse.storage.databases.main.event_push_actions - 615 - INFO - main - Searching for stream ordering 1 day ago
2022-03-23 16:39:25,839 - synapse.storage.databases.main.event_push_actions - 619 - INFO - main - Found stream ordering 1 day ago: it's 0
2022-03-23 16:39:25,839 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1
2022-03-23 16:39:25,839 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1
2022-03-23 16:39:25,839 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1
2022-03-23 16:39:25,840 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1
2022-03-23 16:39:25,841 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1
2022-03-23 16:39:25,841 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1
2022-03-23 16:39:25,841 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1
2022-03-23 16:39:25,842 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1
2022-03-23 16:39:25,842 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1
2022-03-23 16:39:25,842 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1
2022-03-23 16:39:25,842 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1
2022-03-23 16:39:25,843 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 2
2022-03-23 16:39:25,843 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
2022-03-23 16:39:25,843 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1
2022-03-23 16:39:25,844 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2022-03-23 16:39:25,844 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared
2022-03-23 16:39:25,844 - synapse.server - 317 - INFO - main - Finished setting up.
2022-03-23 16:39:25,850 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False
2022-03-23 16:39:25,851 - synapse.federation.federation_server - 1296 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
2022-03-23 16:39:25,851 - synapse.federation.federation_server - 1316 - INFO - main - Registering federation query handler for 'profile'
2022-03-23 16:39:25,852 - synapse.federation.federation_server - 1296 - INFO - main - Registering federation EDU handler for 'm.presence'
2022-03-23 16:39:25,852 - synapse.federation.federation_server - 1296 - INFO - main - Registering federation EDU handler for 'm.typing'
2022-03-23 16:39:25,853 - synapse.federation.federation_server - 1316 - INFO - main - Registering federation query handler for 'directory'
2022-03-23 16:39:25,853 - twisted - 283 - INFO - main - Redirected stdout/stderr to logs
2022-03-23 16:39:25,853 - synapse.app.homeserver - 156 - INFO - sentinel - Running
2022-03-23 16:39:25,855 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576
2022-03-23 16:39:25,855 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter
2022-03-23 16:39:25,859 - synapse.config.tls - 260 - INFO - sentinel - Loading TLS key from /conf/server.tls.key
2022-03-23 16:39:25,860 - synapse.config.tls - 247 - INFO - sentinel - Loading TLS certificate from /conf/server.tls.crt
2022-03-23 16:39:25,860 - synapse.util.caches.lrucache - 164 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2022-03-23 16:39:25,868 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/health'
2022-03-23 16:39:25,868 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/federation'
2022-03-23 16:39:25,868 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/r0'
2022-03-23 16:39:25,868 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v3'
2022-03-23 16:39:25,869 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v1'
2022-03-23 16:39:25,869 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/key/v2'
2022-03-23 16:39:25,869 - twisted - 283 - INFO - sentinel - SynapseSite (TLS) starting on 8448
2022-03-23 16:39:25,869 - synapse.app.homeserver - 167 - INFO - sentinel - Synapse now listening on TCP port 8448 (TLS)
2022-03-23 16:39:25,878 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
2022-03-23 16:39:25,878 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
2022-03-23 16:39:25,878 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
2022-03-23 16:39:25,879 - synapse.federation.federation_server - 1316 - INFO - sentinel - Registering federation query handler for 'client_keys'
2022-03-23 16:39:25,879 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
2022-03-23 16:39:25,880 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/health'
2022-03-23 16:39:25,880 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/client'
2022-03-23 16:39:25,881 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/.well-known'
2022-03-23 16:39:25,881 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/admin'
2022-03-23 16:39:25,881 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/pick_idp'
2022-03-23 16:39:25,881 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/pick_username'
2022-03-23 16:39:25,881 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/new_user_consent'
2022-03-23 16:39:25,881 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/sso_register'
2022-03-23 16:39:25,882 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static'
2022-03-23 16:39:25,882 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/r0'
2022-03-23 16:39:25,882 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v3'
2022-03-23 16:39:25,882 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v1'
2022-03-23 16:39:25,885 - twisted - 283 - INFO - sentinel - SynapseSite starting on 8008
2022-03-23 16:39:25,885 - synapse.app.homeserver - 176 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-03-23 16:39:25,934 - synapse.storage.background_updates - 277 - INFO - background_updates-0 - Starting background schema updates
2022-03-23 16:39:25,935 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-03-23 16:39:25,936 - synapse.push.pusherpool - 314 - INFO - start_pushers-0 - Started pushers
2022-03-23 16:39:26,850 - synapse.access.http.8008 - 427 - INFO - GET-1 - ::ffff:192.168.0.1 - 8008 - {None} Processed request: 0.001sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 556B 200 "GET /_matrix/client/versions HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:26,938 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'add_rooms_room_version_column'
2022-03-23 16:39:30,821 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'add_rooms_room_version_column'. Processed 100 items in 3882ms. (total_rate=0.02575991756826378/ms, current_rate=0.02575991756826378/ms, total_updated=100, batch_size=100)
2022-03-23 16:39:30,822 - synapse.access.http.8008 - 427 - INFO - GET-3 - ::ffff:192.168.0.1 - 8008 - {@alice:hs1} Processed request: 2.245sec/0.001sec (0.000sec, 0.000sec) (2.241sec/0.000sec/1) 558B 200 "GET /_matrix/client/r0/capabilities HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:30,828 - synapse.http.servlet - 663 - WARNING - POST-4 - Unable to parse JSON: Expecting value: line 1 column 1 (char 0) (b'')
2022-03-23 16:39:30,853 - synapse.access.https.8448 - 427 - INFO - GET-5 - ::ffff:192.168.0.1 - 8448 - {None} Processed request: 0.000sec/-0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 289B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:30,854 - synapse.http.matrixfederationclient - 291 - INFO - POST-4 - {GET-O-1} [host.docker.internal:43483] Completed request: 200 OK in 0.02 secs, got 404 bytes - GET matrix://host.docker.internal:43483/_matrix/federation/v1/make_join/%210%3Ahost.docker.internal%3A43483/%40alice%3Ahs1?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=7&ver=8&ver=9&ver=org.matrix.msc2716v3
2022-03-23 16:39:30,871 - synapse.access.https.8448 - 427 - INFO - GET-6 - ::ffff:192.168.0.1 - 8448 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 289B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:30,874 - synapse.http.matrixfederationclient - 291 - INFO - POST-4 - {PUT-O-2} [host.docker.internal:43483] Completed request: 200 OK in 0.01 secs, got 5061 bytes - PUT matrix://host.docker.internal:43483/_matrix/federation/v2/send_join/%210%3Ahost.docker.internal%3A43483/%24-hBQ65Vh_R_kovhG2Xqx5MDyW7-Zu5pIQJN2hrC1MfY
2022-03-23 16:39:30,874 - synapse.federation.federation_client - 904 - INFO - POST-4 - Processing from send_join 7 events
2022-03-23 16:39:30,877 - synapse.http.matrixfederationclient - 291 - INFO - ServerKeyFetcher-0 - {GET-O-3} [host.docker.internal:43483] Completed request: 200 OK in 0.00 secs, got 343 bytes - GET matrix://host.docker.internal:43483/_matrix/key/v2/server/ed25519%3Acomplement
2022-03-23 16:39:31,010 - synapse.handlers.federation_event - 1308 - INFO - POST-4 - Persisting 1 of 4 remaining outliers: ['$tfBN8KW33d2VvF0EnSTmQfseu4jFLlqwWNfm9Wig1lc']
2022-03-23 16:39:31,047 - synapse.handlers.federation_event - 1308 - INFO - POST-4 - Persisting 1 of 3 remaining outliers: ['$AqxMbxaFZbh7O8IT_Dwqga-Hv9KeQJRwT3oIbR6mRLA']
2022-03-23 16:39:31,091 - synapse.handlers.federation_event - 1308 - INFO - POST-4 - Persisting 1 of 2 remaining outliers: ['$D8D0ehXXh10LwOEkxoNkDPtAvArRu0LskX3iS2ARMiM']
2022-03-23 16:39:31,151 - synapse.handlers.federation_event - 1308 - INFO - POST-4 - Persisting 1 of 1 remaining outliers: ['$nJbugq47hKEwiSvT68Yd8d0eCuzTxRuMkPk1i5fTKEc']
2022-03-23 16:39:31,823 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'current_state_events_membership'
2022-03-23 16:39:31,852 - synapse.handlers.federation_event - 483 - INFO - POST-4 - Peristing join-via-remote  (partial_state: False)
2022-03-23 16:39:33,203 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'current_state_events_membership'. Processed 0 items in 1350ms. (total_rate=None/ms, current_rate=None/ms, total_updated=0, batch_size=100)
2022-03-23 16:39:33,826 - synapse.access.http.8008 - 427 - INFO - POST-4 - ::ffff:192.168.0.1 - 8008 - {@alice:hs1} Processed request: 2.998sec/0.001sec (0.011sec, 0.001sec) (0.014sec/0.902sec/18) 43B 200 "POST /_matrix/client/r0/join/%210:host.docker.internal:43483?server_name=host.docker.internal%3A43483 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:34,204 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'
2022-03-23 16:39:35,103 - synapse.storage.databases.main.state - 443 - INFO - background_updates-0 - skipping rooms which are being created: set()
2022-03-23 16:39:35,103 - synapse.storage.databases.main.state - 459 - INFO - background_updates-0 - Deleting current state left rooms: set()
2022-03-23 16:39:55,861 - synapse.util.caches.lrucache - 154 - INFO - LruCache._expire_old_entries-0 - Dropped 0 items from caches
2022-03-23 16:40:03,828 - synapse.http.site - 353 - INFO - GET-9 - Connection from client lost before response was sent
2022-03-23 16:40:18,796 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 100 items in 44507ms. (total_rate=0.002246837576111623/ms, current_rate=0.002246837576111623/ms, total_updated=100, batch_size=100)
2022/03/23 12:40:18 ============== 2dcc0509705e63a2e79e66e71180f8af1fe5e1aee1ccaa96faeaf3d4e6596d7a : END LOGS ==============
=== FAIL: tests/csapi TestInviteFromIgnoredUsersDoesNotAppearInSync (75.51s)
    ignored_users_test.go:28: Deploy times: 3.745891507s blueprints, 2.821532695s containers
    client.go:546: POST hs1/_matrix/client/r0/register => 200 OK (5.086057434s)
    client.go:544: POST hs1/_matrix/client/r0/register => error: net/http: request canceled (30.000409206s)
    ignored_users_test.go:31: CSAPI.DoFunc response returned error: Post "http://localhost:49274/_matrix/client/r0/register": net/http: request canceled (Client.Timeout exceeded while awaiting headers)
2022/03/23 12:40:18 ============================================
2022/03/23 12:40:18 5b7a1812b416fb0e8ffd7b375ee0c125e041fc00aa14b5df7fb07af7373a2b9e : Server logs:
Signature ok
subject=CN = hs1
Getting CA Private Key
2022-03-23 16:39:25,052 - root - 352 - WARNING - main - ***** STARTING SERVER *****
2022-03-23 16:39:25,052 - root - 353 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.55.0
2022-03-23 16:39:25,052 - root - 358 - INFO - main - Server hostname: hs1
2022-03-23 16:39:25,052 - root - 359 - INFO - main - Instance name: master
2022-03-23 16:39:25,052 - synapse.app.homeserver - 359 - INFO - main - Setting up server
2022-03-23 16:39:25,052 - synapse.server - 314 - INFO - main - Setting up.
2022-03-23 16:39:25,072 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2022-03-23 16:39:25,073 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2022-03-23 16:39:25,073 - synapse.storage.prepare_database - 116 - INFO - main - ['main', 'state']: Checking existing schema version
2022-03-23 16:39:25,077 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Existing schema is 68 (+7 deltas)
2022-03-23 16:39:25,077 - synapse.storage.databases.main - 355 - INFO - main - Checking database for consistency with configuration...
2022-03-23 16:39:25,077 - synapse.storage.prepare_database - 412 - INFO - main - Applying schema deltas for v68
2022-03-23 16:39:25,078 - synapse.storage.prepare_database - 547 - INFO - main - Schema now up to date
2022-03-23 16:39:25,091 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database
2022-03-23 16:39:25,091 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 1
2022-03-23 16:39:25,091 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1
2022-03-23 16:39:25,091 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1
2022-03-23 16:39:25,092 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1
2022-03-23 16:39:25,092 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1
2022-03-23 16:39:25,092 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for local_group_updates(stream_id): 1
2022-03-23 16:39:25,092 - synapse.config.appservice - 59 - WARNING - main - Expected None to be a list of AS config files.
2022-03-23 16:39:25,092 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1
2022-03-23 16:39:25,093 - synapse.storage.databases.main.event_push_actions - 608 - INFO - main - Searching for stream ordering 1 month ago
2022-03-23 16:39:25,094 - synapse.storage.databases.main.event_push_actions - 612 - INFO - main - Found stream ordering 1 month ago: it's 0
2022-03-23 16:39:25,094 - synapse.storage.databases.main.event_push_actions - 615 - INFO - main - Searching for stream ordering 1 day ago
2022-03-23 16:39:25,094 - synapse.storage.databases.main.event_push_actions - 619 - INFO - main - Found stream ordering 1 day ago: it's 0
2022-03-23 16:39:25,094 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1
2022-03-23 16:39:25,094 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1
2022-03-23 16:39:25,095 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1
2022-03-23 16:39:25,096 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1
2022-03-23 16:39:25,097 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1
2022-03-23 16:39:25,097 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1
2022-03-23 16:39:25,097 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1
2022-03-23 16:39:25,098 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1
2022-03-23 16:39:25,098 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1
2022-03-23 16:39:25,098 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1
2022-03-23 16:39:25,099 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1
2022-03-23 16:39:25,099 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 1
2022-03-23 16:39:25,099 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
2022-03-23 16:39:25,100 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1
2022-03-23 16:39:25,100 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2022-03-23 16:39:25,101 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared
2022-03-23 16:39:25,101 - synapse.server - 317 - INFO - main - Finished setting up.
2022-03-23 16:39:25,109 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False
2022-03-23 16:39:25,111 - synapse.federation.federation_server - 1296 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
2022-03-23 16:39:25,111 - synapse.federation.federation_server - 1316 - INFO - main - Registering federation query handler for 'profile'
2022-03-23 16:39:25,112 - synapse.federation.federation_server - 1296 - INFO - main - Registering federation EDU handler for 'm.presence'
2022-03-23 16:39:25,112 - synapse.federation.federation_server - 1296 - INFO - main - Registering federation EDU handler for 'm.typing'
2022-03-23 16:39:25,113 - synapse.federation.federation_server - 1316 - INFO - main - Registering federation query handler for 'directory'
2022-03-23 16:39:25,113 - twisted - 283 - INFO - main - Redirected stdout/stderr to logs
2022-03-23 16:39:25,113 - synapse.app.homeserver - 156 - INFO - sentinel - Running
2022-03-23 16:39:25,114 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576
2022-03-23 16:39:25,115 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter
2022-03-23 16:39:25,116 - synapse.config.tls - 260 - INFO - sentinel - Loading TLS key from /conf/server.tls.key
2022-03-23 16:39:25,116 - synapse.config.tls - 247 - INFO - sentinel - Loading TLS certificate from /conf/server.tls.crt
2022-03-23 16:39:25,117 - synapse.util.caches.lrucache - 164 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2022-03-23 16:39:25,124 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/health'
2022-03-23 16:39:25,126 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/federation'
2022-03-23 16:39:25,126 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/r0'
2022-03-23 16:39:25,126 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v3'
2022-03-23 16:39:25,126 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v1'
2022-03-23 16:39:25,126 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/key/v2'
2022-03-23 16:39:25,128 - twisted - 283 - INFO - sentinel - SynapseSite (TLS) starting on 8448
2022-03-23 16:39:25,128 - synapse.app.homeserver - 167 - INFO - sentinel - Synapse now listening on TCP port 8448 (TLS)
2022-03-23 16:39:25,137 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
2022-03-23 16:39:25,137 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
2022-03-23 16:39:25,137 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
2022-03-23 16:39:25,137 - synapse.federation.federation_server - 1316 - INFO - sentinel - Registering federation query handler for 'client_keys'
2022-03-23 16:39:25,137 - synapse.federation.federation_server - 1296 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/health'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/client'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/.well-known'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/admin'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/pick_idp'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/pick_username'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/new_user_consent'
2022-03-23 16:39:25,139 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_synapse/client/sso_register'
2022-03-23 16:39:25,140 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static'
2022-03-23 16:39:25,140 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/r0'
2022-03-23 16:39:25,140 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v3'
2022-03-23 16:39:25,140 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching  to path b'/_matrix/media/v1'
2022-03-23 16:39:25,140 - twisted - 283 - INFO - sentinel - SynapseSite starting on 8008
2022-03-23 16:39:25,141 - synapse.app.homeserver - 176 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-03-23 16:39:25,181 - synapse.storage.background_updates - 277 - INFO - background_updates-0 - Starting background schema updates
2022-03-23 16:39:25,181 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-03-23 16:39:25,181 - synapse.push.pusherpool - 314 - INFO - start_pushers-0 - Started pushers
2022-03-23 16:39:25,985 - synapse.access.http.8008 - 427 - INFO - GET-1 - ::ffff:192.168.48.1 - 8008 - {None} Processed request: 0.001sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 556B 200 "GET /_matrix/client/versions HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:26,184 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'add_rooms_room_version_column'
2022-03-23 16:39:26,648 - synapse.handlers.auth - 589 - INFO - POST-2 - Auth completed with creds: {'m.login.dummy': True}. Client dict has keys: ['username']
2022-03-23 16:39:26,844 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'add_rooms_room_version_column'. Processed 100 items in 320ms. (total_rate=0.3125/ms, current_rate=0.3125/ms, total_updated=100, batch_size=100)
2022-03-23 16:39:27,848 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'current_state_events_membership'
2022-03-23 16:39:30,861 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'current_state_events_membership'. Processed 0 items in 44ms. (total_rate=None/ms, current_rate=None/ms, total_updated=0, batch_size=100)
2022-03-23 16:39:31,025 - synapse.handlers.auth - 974 - INFO - POST-2 - Logging in user @alice:hs1 on device HEEBFERDWB
2022-03-23 16:39:31,071 - synapse.access.http.8008 - 427 - INFO - POST-2 - ::ffff:192.168.48.1 - 8008 - {None} Processed request: 5.083sec/0.000sec (0.013sec, 0.000sec) (0.238sec/4.827sec/21) 126B 200 "POST /_matrix/client/r0/register HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2022-03-23 16:39:31,863 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'delete_old_current_state_events'
2022-03-23 16:39:31,998 - synapse.handlers.auth - 589 - INFO - POST-4 - Auth completed with creds: {'m.login.dummy': True}. Client dict has keys: ['username']
2022-03-23 16:39:32,462 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'delete_old_current_state_events'. Processed 100 items in 465ms. (total_rate=0.21505376344086022/ms, current_rate=0.21505376344086022/ms, total_updated=100, batch_size=100)
2022-03-23 16:39:33,464 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'devices_last_seen'
2022-03-23 16:39:34,906 - synapse.storage.background_updates - 454 - INFO - background_updates-0 - Running background update 'devices_last_seen'. Processed 0 items in 875ms. (total_rate=None/ms, current_rate=None/ms, total_updated=0, batch_size=100)
2022-03-23 16:39:35,170 - synapse.handlers.auth - 974 - INFO - POST-4 - Logging in user @bob:hs1 on device OKDEOVEKBY
2022-03-23 16:39:36,172 - synapse.storage.background_updates - 411 - INFO - background_updates-0 - Starting update batch on background update 'event_store_labels'
2022-03-23 16:39:55,118 - synapse.util.caches.lrucache - 154 - INFO - LruCache._expire_old_entries-0 - Dropped 0 items from caches
2022-03-23 16:40:01,073 - synapse.http.site - 353 - INFO - POST-4 - Connection from client lost before response was sent
2022/03/23 12:40:18 ============== 5b7a1812b416fb0e8ffd7b375ee0c125e041fc00aa14b5df7fb07af7373a2b9e : END LOGS ==============

Additional context

Using the synapse 1.55 release tag (with some patches) as well as complement 1b29ad8
@ShadowJonathan
Copy link
Contributor

Note: This synapse is forked, the CI run is using 68bfb503

@kegsay
Copy link
Member

kegsay commented Mar 25, 2022

It looks like random CS API requests time out after 30s. Different endpoints: sometimes /sync, sometimes /register. This doesn't seem to be a complement problem.

@ShadowJonathan
Copy link
Contributor

ShadowJonathan commented Mar 25, 2022 •
edited
Loading

This also happened only one time, unless random timeouts happen more, i believe this is non-actionable.

@deepbluev7
Copy link
Author

Well, I wasn't sure where to file it, I just noticed that randomly failing and since people complain, when I don't file every issue I run into, I rolled a dice if I file it on Synapse or Complement. Feel free to move it or delete it.

@kegsay kegsay closed this as completed Mar 28, 2022
@DMRobertson DMRobertson mentioned this issue Sep 16, 2022
Open
@matrixbot matrixbot mentioned this issue Dec 21, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@kegsay @deepbluev7 @ShadowJonathan