matrix-org / sydent

Sydent: Reference Matrix Identity Server
http://matrix.org
Apache License 2.0
293 stars 84 forks source link

MatrixError: [502] Third party certificate could not be checked #577

Closed daedric7 closed 12 months ago

daedric7 commented 1 year ago

It has been detected that the final steps of inviting someone from outside Matrix to a room, via email, ends in the issue error.

Details:

Selfhosted Synapse, Element and Sydent.

Versions:

Sydent: Unknown, git cloned and built into a docker container recently.

{"versions": ["r0.1.0", "r0.2.0", "r0.2.1", "r0.3.0", "v1.1", "v1.2", "v1.3", "v1.4", "v1.5"]}

Synapse:

Synapse 1.93.0rc1

Element:

versão do AguiarVieira.pt: 1.11.45
Olm version: 3.2.14

Process:

image

image

Link:

https://aguiarvieira.pt/#/room/%21tnOYhXKUIldKCOOyzb%3Aaguiarvieira.pt?via=aguiarvieira.pt&email=test06%40aguiarvieira.pt&signurl=https%3A%2F%2Faguiarvieira.pt%2F_matrix%2Fidentity%2Fapi%2Fv1%2Fsign-ed25519%3Ftoken%3DwHvIjathcHQKsuRLpWKAyaYQUaKROdYKDlyUknKEDBsctLLWZMqnRUHDmxUyMJCMeukCMKsmmaxSuNjtUBlwwuENCuiFQTDfEsOlkUybgwCAuYwRZpVhVtrMzcuNgxjc%26private_key%3Dr_mudF73hVkAs5ucDoEBH39ArOulhd1U2GMSX2OnKhI&room_name=Wallpapers&room_avatar_url=mxc%3A//aguiarvieira.pt/b2c0a20111de0dcd2b9a8cfb648889604c1433f01703102296830771200&inviter_name=Ricardo&guest_access_token=&guest_user_id=&room_type=

image

Link:

https://aguiarvieira.pt/_matrix/client/unstable/registration/email/submit_token?token=zJALrZdsupCCmWlHSMORFWqthtLUMDqp&client_secret=cR7qO6TxLL9Q6hdiQF3rB47bTruEprOF&sid=wiiphWcNVCCOJfqj

Synapse logs that i could find (there are 20 workers... there may be more but i found nothing relevant):

matrix-worker-2  | 2023-09-30 22:12:10,848 - synapse.crypto.event_signing - 155 - DEBUG - POST-134 - Signing event: b'{"auth_events":["$o_EJiwMcWl8bhViiAh554BJ_zxoCbNy60g9oZr9kXng","$FXcbZ57l0rFIWDfH9vZt36l5ib9NaZcodbU7HnbyP_8","$rd-r_EYxa9WJyC4qMG1c4Bzn9PK0xXEhcjYKaIZcHZo","$NsoCdQ3jhSo4pxzS2hlZIsrh8bJc227cehANNGOqj34","$FUw9WECjMiIJI5H099-h_UJxzNkPWg3Kb239G8RHl3Y"],"content":{"membership":"invite"},"depth":1772,"hashes":{"sha256":"/eajdooyVfeVfOmf7EZ9ayh8JrcK9XgCONXEUNTwjm4"},"origin":"aguiarvieira.pt","origin_server_ts":1696111930848,"prev_events":["$FXcbZ57l0rFIWDfH9vZt36l5ib9NaZcodbU7HnbyP_8"],"room_id":"!tnOYhXKUIldKCOOyzb:aguiarvieira.pt","sender":"@daedric:aguiarvieira.pt","signatures":{},"state_key":"@test06:aguiarvieira.pt","type":"m.room.member"}'
matrix-worker-2  | 2023-09-30 22:12:10,848 - synapse.crypto.event_signing - 158 - DEBUG - POST-134 - Signed event: b'{"auth_events":["$o_EJiwMcWl8bhViiAh554BJ_zxoCbNy60g9oZr9kXng","$FXcbZ57l0rFIWDfH9vZt36l5ib9NaZcodbU7HnbyP_8","$rd-r_EYxa9WJyC4qMG1c4Bzn9PK0xXEhcjYKaIZcHZo","$NsoCdQ3jhSo4pxzS2hlZIsrh8bJc227cehANNGOqj34","$FUw9WECjMiIJI5H099-h_UJxzNkPWg3Kb239G8RHl3Y"],"content":{"membership":"invite"},"depth":1772,"hashes":{"sha256":"/eajdooyVfeVfOmf7EZ9ayh8JrcK9XgCONXEUNTwjm4"},"origin":"aguiarvieira.pt","origin_server_ts":1696111930848,"prev_events":["$FXcbZ57l0rFIWDfH9vZt36l5ib9NaZcodbU7HnbyP_8"],"room_id":"!tnOYhXKUIldKCOOyzb:aguiarvieira.pt","sender":"@daedric:aguiarvieira.pt","signatures":{"aguiarvieira.pt":{"ed25519:a_Yofy":"p4ut6e0VsAaZ13sF3j8lx6yHiVbHyl0cDeeqywmGwSGzFuwgj6ns6YI7ZzXXWbXCvwOZG4HrjzouXDvzYMbpBA"}},"state_key":"@test06:aguiarvieira.pt","type":"m.room.member"}'
matrix-worker-2  | 2023-09-30 22:12:10,849 - synapse.state - 342 - DEBUG - POST-134 - calling resolve_state_groups from compute_event_context
matrix-worker-2  | 2023-09-30 22:12:10,849 - synapse.util.metrics - 163 - DEBUG - POST-134 - Entering block resolve_state_groups_for_events
matrix-worker-2  | 2023-09-30 22:12:10,849 - synapse.state - 490 - DEBUG - POST-134 - resolve_state_groups event_ids ['$FXcbZ57l0rFIWDfH9vZt36l5ib9NaZcodbU7HnbyP_8']
matrix-worker-2  | 2023-09-30 22:12:10,849 - synapse.util.metrics - 176 - DEBUG - POST-134 - Exiting block resolve_state_groups_for_events
matrix-worker-2  | 2023-09-30 22:12:10,851 - synapse.handlers.message - 1309 - DEBUG - POST-134 - Created event $SSf4RfVX4269LylzIMnTDhoHbIWLf5DbH9keVkEt_fs
matrix-worker-2  | 2023-09-30 22:12:10,851 - synapse.util.metrics - 176 - DEBUG - POST-134 - Exiting block create_new_client_event
matrix-worker-2  | 2023-09-30 22:12:10,852 - synapse.storage.txn - 754 - DEBUG - POST-134 - [TXN START] {store_state_group.insert_delta_group-3ce}
matrix-worker-2  | 2023-09-30 22:12:10,852 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {store_state_group.insert_delta_group-3ce} SELECT id FROM state_groups WHERE id = ?
matrix-worker-2  | 2023-09-30 22:12:10,852 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {store_state_group.insert_delta_group-3ce} [15377]
matrix-worker-2  | 2023-09-30 22:12:10,852 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {store_state_group.insert_delta_group-3ce} 0.000761 sec
matrix-worker-2  | 2023-09-30 22:12:10,853 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {store_state_group.insert_delta_group-3ce} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT count(*) FROM state;
matrix-worker-2  | 2023-09-30 22:12:10,853 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {store_state_group.insert_delta_group-3ce} (15377,)
matrix-worker-2  | 2023-09-30 22:12:10,853 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {store_state_group.insert_delta_group-3ce} 0.000694 sec
matrix-worker-2  | 2023-09-30 22:12:10,854 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {store_state_group.insert_delta_group-3ce} SELECT nextval(?)
matrix-worker-2  | 2023-09-30 22:12:10,854 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {store_state_group.insert_delta_group-3ce} ('state_group_id_seq',)
matrix-worker-2  | 2023-09-30 22:12:10,854 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {store_state_group.insert_delta_group-3ce} 0.000402 sec
matrix-worker-2  | 2023-09-30 22:12:10,854 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {store_state_group.insert_delta_group-3ce} INSERT INTO state_groups (id, room_id, event_id) VALUES(?, ?, ?)
matrix-worker-2  | 2023-09-30 22:12:10,854 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {store_state_group.insert_delta_group-3ce} (15384, '!tnOYhXKUIldKCOOyzb:aguiarvieira.pt', '$SSf4RfVX4269LylzIMnTDhoHbIWLf5DbH9keVkEt_fs')
matrix-worker-2  | 2023-09-30 22:12:10,855 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {store_state_group.insert_delta_group-3ce} 0.000291 sec
matrix-worker-2  | 2023-09-30 22:12:10,855 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {store_state_group.insert_delta_group-3ce} INSERT INTO state_group_edges (state_group, prev_state_group) VALUES(?, ?)
matrix-worker-2  | 2023-09-30 22:12:10,855 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {store_state_group.insert_delta_group-3ce} (15384, 15377)
matrix-worker-2  | 2023-09-30 22:12:10,855 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {store_state_group.insert_delta_group-3ce} 0.000284 sec
matrix-worker-2  | 2023-09-30 22:12:10,855 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {store_state_group.insert_delta_group-3ce} INSERT INTO state_groups_state (state_group, room_id, type, state_key, event_id) VALUES ?
matrix-worker-2  | 2023-09-30 22:12:10,855 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {store_state_group.insert_delta_group-3ce} [(15384, '!tnOYhXKUIldKCOOyzb:aguiarvieira.pt', 'm.room.member', '@test06:aguiarvieira.pt', '$SSf4RfVX4269LylzIMnTDhoHbIWLf5DbH9keVkEt_fs')]
matrix-worker-2  | 2023-09-30 22:12:10,856 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {store_state_group.insert_delta_group-3ce} 0.000268 sec
matrix-worker-2  | 2023-09-30 22:12:10,856 - synapse.storage.txn - 858 - DEBUG - POST-134 - [TXN END] {store_state_group.insert_delta_group-3ce} 0.004398 sec
matrix-worker-2  | 2023-09-30 22:12:10,857 - synapse.event_auth - 534 - DEBUG - POST-134 - _is_membership_change_allowed: {'caller_in_room': True, 'caller_invited': False, 'caller_knocked': False, 'target_banned': None, 'target_in_room': None, 'membership': 'invite', 'join_rule': 'public', 'target_user_id': '@test06:aguiarvieira.pt', 'event.user_id': '@daedric:aguiarvieira.pt'}
matrix-worker-2  | 2023-09-30 22:12:10,858 - synapse.event_auth - 312 - DEBUG - POST-134 - Allowing! <FrozenEventV3 event_id=$SSf4RfVX4269LylzIMnTDhoHbIWLf5DbH9keVkEt_fs, type=m.room.member, state_key=@test06:aguiarvieira.pt, outlier=False>
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1663 - DEBUG - POST-134 - Checking auth on event {'membership': 'invite', 'third_party_invite': {'signed': {'mxid': '@test06:aguiarvieira.pt', 'sender': '@daedric:aguiarvieira.pt', 'token': 'wHvIjathcHQKsuRLpWKAyaYQUaKROdYKDlyUknKEDBsctLLWZMqnRUHDmxUyMJCMeukCMKsmmaxSuNjtUBlwwuENCuiFQTDfEsOlkUybgwCAuYwRZpVhVtrMzcuNgxjc', 'signatures': {'aguiarvieira.pt': {'ed25519:0': 'tbFw8CPq20pa/2kK8zh2nnG+zkU03ZcdfoG9MRsKSQzTnZoQ5UlaMIVur940PRZwqY1EyE4OU0JbgJTfzYexDA'}}}, 'display_name': 'tes...@agu...'}}
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1676 - DEBUG - POST-134 - Attempting to verify sig with key ed25519:0 from 'aguiarvieira.pt' against pubkey {'public_key': 'H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg', 'key_validity_url': 'https://aguiarvieira.pt/_matrix/identity/v2/pubkey/isvalid'}
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1698 - INFO - POST-134 - Failed to verify sig with key ed25519:0 from 'aguiarvieira.pt' against pubkey {'public_key': 'H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg', 'key_validity_url': 'https://aguiarvieira.pt/_matrix/identity/v2/pubkey/isvalid'}
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1676 - DEBUG - POST-134 - Attempting to verify sig with key ed25519:0 from 'aguiarvieira.pt' against pubkey {'key_validity_url': '/_matrix/identity/api/v1/pubkey/isvalid', 'public_key': 'H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg'}
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1698 - INFO - POST-134 - Failed to verify sig with key ed25519:0 from 'aguiarvieira.pt' against pubkey {'key_validity_url': '/_matrix/identity/api/v1/pubkey/isvalid', 'public_key': 'H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg'}
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1676 - DEBUG - POST-134 - Attempting to verify sig with key ed25519:0 from 'aguiarvieira.pt' against pubkey {'key_validity_url': '/_matrix/identity/api/v1/pubkey/ephemeral/isvalid', 'public_key': 'fK46giIll7mMcBDZ9uC-Chy3USS3_YXiT1cfD42Og8I'}
matrix-worker-2  | 2023-09-30 22:12:10,859 - synapse.handlers.federation - 1690 - DEBUG - POST-134 - Successfully verified sig with key ed25519:0 from 'aguiarvieira.pt' against pubkey {'key_validity_url': '/_matrix/identity/api/v1/pubkey/ephemeral/isvalid', 'public_key': 'fK46giIll7mMcBDZ9uC-Chy3USS3_YXiT1cfD42Og8I'}
matrix-worker-2  | 2023-09-30 22:12:10,860 - synapse.http.client - 368 - DEBUG - POST-134 - Sending request GET /_matrix/identity/api/v1/pubkey/ephemeral/isvalid?public_key=fK46giIll7mMcBDZ9uC-Chy3USS3_YXiT1cfD42Og8I
matrix-worker-2  | 2023-09-30 22:12:10,860 - synapse.http.proxyagent - 313 - DEBUG - POST-134 - Requesting /_matrix/identity/api/v1/pubkey/ephemeral/isvalid?public_key=fK46giIll7mMcBDZ9uC-Chy3USS3_YXiT1cfD42Og8I via <HostnameEndpoint :80>
matrix-worker-2  | 2023-09-30 22:12:10,860 - synapse.http.client - 422 - INFO - POST-134 - Error sending request to  GET /_matrix/identity/api/v1/pubkey/ephemeral/isvalid?public_key=fK46giIll7mMcBDZ9uC-Chy3USS3_YXiT1cfD42Og8I: SchemeNotSupported Unsupported scheme: b''
matrix-worker-2  | 2023-09-30 22:12:10,860 - synapse.handlers.federation - 1712 - INFO - POST-134 - Failed to query key_validity_url /_matrix/identity/api/v1/pubkey/ephemeral/isvalid
matrix-worker-2  | 2023-09-30 22:12:10,862 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
matrix-worker-2  | 2023-09-30 22:12:10,862 - synapse.storage.txn - 754 - DEBUG - POST-134 - [TXN START] {drop_lock-3cf}
matrix-worker-2  | 2023-09-30 22:12:10,865 - synapse.storage.SQL - 465 - DEBUG - POST-134 - [SQL] {drop_lock-3cf} DELETE FROM worker_read_write_locks WHERE lock_name = ? AND lock_key = ? AND token = ?
matrix-worker-2  | 2023-09-30 22:12:10,865 - synapse.storage.SQL - 470 - DEBUG - POST-134 - [SQL values] {drop_lock-3cf} ['new_event_during_purge_lock', '!tnOYhXKUIldKCOOyzb:aguiarvieira.pt', 'XMalKp']
matrix-worker-2  | 2023-09-30 22:12:10,866 - synapse.storage.SQL - 491 - DEBUG - POST-134 - [SQL time] {drop_lock-3cf} 0.001472 sec
matrix-worker-2  | 2023-09-30 22:12:10,867 - synapse.storage.txn - 858 - DEBUG - POST-134 - [TXN END] {drop_lock-3cf} 0.005045 sec
matrix-worker-2  | 2023-09-30 22:12:10,874 - synapse.util.async_helpers - 534 - DEBUG - POST-134 - Releasing linearizer lock 'member' for key ('!tnOYhXKUIldKCOOyzb:aguiarvieira.pt',)
matrix-worker-2  | 2023-09-30 22:12:10,874 - synapse.util.async_helpers - 534 - DEBUG - POST-134 - Releasing linearizer lock 'member_as_limiter' for key <object object at 0xffff9f3f1640>
matrix-worker-2  | 2023-09-30 22:12:10,874 - synapse.http.server - 124 - INFO - POST-134 - <XForwardedForRequest at 0xffff90aedc10 method='POST' uri='/_matrix/client/v3/join/!tnOYhXKUIldKCOOyzb%3Aaguiarvieira.pt' clientproto='HTTP/1.1' site='unix'> SynapseError: 502 - Third party certificate could not be checked
matrix-worker-2  | 2023-09-30 22:12:10,875 - synapse.access.http.unix - 465 - INFO - POST-134 - 2.82.30.18 - unix - {@test06:aguiarvieira.pt} Processed request: 0.073sec/0.001sec (0.020sec, 0.002sec) (0.002sec/0.035sec/7) 78B 502 "POST /_matrix/client/v3/join/!tnOYhXKUIldKCOOyzb%3Aaguiarvieira.pt HTTP/1.1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36" [0 dbevts]

Sydent logs:

sydent-sydent-1  | 2023-09-30 22:08:22,670 - sydent.http.httpclient - 56 - DEBUG - HTTP GET matrix://aguiarvieira.pt/_matrix/federation/v1/openid/userinfo?access_token=YcbnTiMikHHFnWJQvtweSOMa
sydent-sydent-1  | 2023-09-30 22:08:22,671 - sydent.http.matrixfederationagent - 353 - INFO - Fetching https://aguiarvieira.pt/.well-known/matrix/server
sydent-sydent-1  | 2023-09-30 22:08:22,793 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0xffff83e518b0>, <twisted.internet.endpoints._WrapperEndpoint object at 0xffff83e5b4f0>)
sydent-sydent-1  | 2023-09-30 22:08:22,810 - sydent.http.matrixfederationagent - 362 - INFO - Response from .well-known: {'m.server': 'aguiarvieira.pt:443'}
sydent-sydent-1  | 2023-09-30 22:08:22,855 - sydent.http.matrixfederationagent - 405 - INFO - Endpoint created with b'aguiarvieira.pt':443
sydent-sydent-1  | 2023-09-30 22:08:22,855 - sydent.http.matrixfederationagent - 410 - INFO - Connecting to aguiarvieira.pt:443
sydent-sydent-1  | 2023-09-30 22:08:22,858 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0xffff83d76ca0>, <twisted.internet.endpoints._WrapperEndpoint object at 0xffff83e875b0>)
sydent-sydent-1  | 2023-09-30 22:08:22,898 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:22 +0000] "POST /_matrix/identity/v2/account/register HTTP/1.1" 200 161 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:08:22,954 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:22 +0000] "GET /_matrix/identity/v2/account HTTP/1.1" 200 39 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:08:23,006 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:22 +0000] "GET /_matrix/identity/v2/hash_details HTTP/1.1" 200 60 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:08:23,060 - sydent.http.servlets.lookupv2servlet - 101 - INFO - Lookup of 1 threepid(s) with algorithm sha256
sydent-sydent-1  | 2023-09-30 22:08:23,061 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:23 +0000] "POST /_matrix/identity/v2/lookup HTTP/1.1" 200 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:08:32,996 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:32 +0000] "GET /_matrix/identity/v2/account HTTP/1.1" 200 39 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:08:33,061 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:33 +0000] "GET /_matrix/identity/v2/hash_details?access_token=4fKDDWuJOgIo1ryISwM3kfoJgyMGzNe3fgdtdikvUKGfsKmpIUxmPwlgxRgdKsBz HTTP/1.1" 200 60 "-" "Synapse/1.93.0rc1"
sydent-sydent-1  | 2023-09-30 22:08:33,065 - sydent.http.servlets.lookupv2servlet - 101 - INFO - Lookup of 1 threepid(s) with algorithm sha256
sydent-sydent-1  | 2023-09-30 22:08:33,065 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:33 +0000] "POST /_matrix/identity/v2/lookup HTTP/1.1" 200 16 "-" "Synapse/1.93.0rc1"
sydent-sydent-1  | 2023-09-30 22:08:33,075 - sydent.http.servlets.store_invite_servlet - 82 - INFO - Store invite request from @daedric:aguiarvieira.pt to test06@aguiarvieira.pt, in !tnOYhXKUIldKCOOyzb:aguiarvieira.pt
sydent-sydent-1  | 2023-09-30 22:08:33,100 - sydent.util.emailutils - 101 - INFO - Sending mail to test06@aguiarvieira.pt with mail server: mail.aguiarvieira.pt
sydent-sydent-1  | 2023-09-30 22:08:34,121 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:08:33 +0000] "POST /_matrix/identity/v2/store-invite HTTP/1.1" 200 514 "-" "Synapse/1.93.0rc1"
sydent-sydent-1  | 2023-09-30 22:09:52,810 - twisted - 147 - INFO - Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0xffff83e518b0>, <twisted.internet.endpoints._WrapperEndpoint object at 0xffff83e5b4f0>)
sydent-sydent-1  | 2023-09-30 22:09:52,872 - twisted - 147 - INFO - Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0xffff83d76ca0>, <twisted.internet.endpoints._WrapperEndpoint object at 0xffff83e875b0>)
sydent-sydent-1  | 2023-09-30 22:10:01,649 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:10:01 +0000] "GET /_matrix/identity/v2 HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:10:06,003 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:10:05 +0000] "GET /_matrix/identity/v2 HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:11:02,327 - sydent.http.httpclient - 56 - DEBUG - HTTP GET matrix://aguiarvieira.pt/_matrix/federation/v1/openid/userinfo?access_token=RmRLrGYIsjPPsMqJuYWezzDh
sydent-sydent-1  | 2023-09-30 22:11:02,364 - sydent.http.matrixfederationagent - 405 - INFO - Endpoint created with b'aguiarvieira.pt':443
sydent-sydent-1  | 2023-09-30 22:11:02,364 - sydent.http.matrixfederationagent - 410 - INFO - Connecting to aguiarvieira.pt:443
sydent-sydent-1  | 2023-09-30 22:11:02,385 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0xffff83e515e0>, <twisted.internet.endpoints._WrapperEndpoint object at 0xffff83e5d8e0>)
sydent-sydent-1  | 2023-09-30 22:11:02,411 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:11:02 +0000] "POST /_matrix/identity/v2/account/register HTTP/1.1" 200 161 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:11:02,463 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:11:02 +0000] "GET /_matrix/identity/v2/account HTTP/1.1" 200 38 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:11:02,513 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:11:02 +0000] "GET /_matrix/identity/v2/terms HTTP/1.1" 200 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:11:05,041 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:11:04 +0000] "GET /_matrix/identity/v2/hash_details HTTP/1.1" 200 60 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:11:05,093 - sydent.http.servlets.lookupv2servlet - 101 - INFO - Lookup of 1 threepid(s) with algorithm sha256
sydent-sydent-1  | 2023-09-30 22:11:05,094 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:11:04 +0000] "POST /_matrix/identity/v2/lookup HTTP/1.1" 200 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:11:08,134 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:11:07 +0000] "POST /_matrix/identity/api/v1/sign-ed25519?token=wHvIjathcHQKsuRLpWKAyaYQUaKROdYKDlyUknKEDBsctLLWZMqnRUHDmxUyMJCMeukCMKsmmaxSuNjtUBlwwuENCuiFQTDfEsOlkUybgwCAuYwRZpVhVtrMzcuNgxjc&private_key=r_mudF73hVkAs5ucDoEBH39ArOulhd1U2GMSX2OnKhI&mxid=%40test06%3Aaguiarvieira.pt HTTP/1.1" 200 354 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:12:10,748 - twisted - 147 - INFO - "::ffff:172.20.0.61" - - [30/Sep/2023:22:12:10 +0000] "POST /_matrix/identity/api/v1/sign-ed25519?token=wHvIjathcHQKsuRLpWKAyaYQUaKROdYKDlyUknKEDBsctLLWZMqnRUHDmxUyMJCMeukCMKsmmaxSuNjtUBlwwuENCuiFQTDfEsOlkUybgwCAuYwRZpVhVtrMzcuNgxjc&private_key=r_mudF73hVkAs5ucDoEBH39ArOulhd1U2GMSX2OnKhI&mxid=%40test06%3Aaguiarvieira.pt HTTP/1.1" 200 354 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
sydent-sydent-1  | 2023-09-30 22:12:32,401 - twisted - 147 - INFO - Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0xffff83e515e0>, <twisted.internet.endpoints._WrapperEndpoint object at 0xffff83e5d8e0>)

Video of the signing in:

https://github.com/matrix-org/sydent/assets/4562461/dbc0d463-348c-4518-b402-0d819298ae92

Request payload:

{"third_party_signed":{"mxid":"@test06:aguiarvieira.pt","sender":"@daedric:aguiarvieira.pt","token":"wHvIjathcHQKsuRLpWKAyaYQUaKROdYKDlyUknKEDBsctLLWZMqnRUHDmxUyMJCMeukCMKsmmaxSuNjtUBlwwuENCuiFQTDfEsOlkUybgwCAuYwRZpVhVtrMzcuNgxjc","signatures":{"aguiarvieira.pt":{"ed25519:0":"tbFw8CPq20pa/2kK8zh2nnG+zkU03ZcdfoG9MRsKSQzTnZoQ5UlaMIVur940PRZwqY1EyE4OU0JbgJTfzYexDA"}}}}

Relevant request:

https://aguiarvieira.pt/_matrix/client/v3/join/!tnOYhXKUIldKCOOyzb%3Aaguiarvieira.pt

richvdh commented 1 year ago

looks like the invite event might have an invalid key_validity_url ? can you "View source" on the invite event?

daedric7 commented 1 year ago

looks like the invite event might have an invalid key_validity_url ? can you "View source" on the invite event?

You might be correct:

{
  "content": {
    "display_name": "tes...@agu...",
    "key_validity_url": "https://aguiarvieira.pt/_matrix/identity/v2/pubkey/isvalid",
    "public_key": "H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg",
    "public_keys": [
      {
        "key_validity_url": "/_matrix/identity/api/v1/pubkey/isvalid",
        "public_key": "H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg"
      },
      {
        "key_validity_url": "/_matrix/identity/api/v1/pubkey/ephemeral/isvalid",
        "public_key": "fK46giIll7mMcBDZ9uC-Chy3USS3_YXiT1cfD42Og8I"
      }
    ]
  },
  "origin_server_ts": 1696111714136,
  "room_id": "!tnOYhXKUIldKCOOyzb:aguiarvieira.pt",
  "sender": "@daedric:aguiarvieira.pt",
  "state_key": "wHvIjathcHQKsuRLpWKAyaYQUaKROdYKDlyUknKEDBsctLLWZMqnRUHDmxUyMJCMeukCMKsmmaxSuNjtUBlwwuENCuiFQTDfEsOlkUybgwCAuYwRZpVhVtrMzcuNgxjc",
  "type": "m.room.third_party_invite",
  "unsigned": {
    "age": 133243859
  },
  "event_id": "$FXcbZ57l0rFIWDfH9vZt36l5ib9NaZcodbU7HnbyP_8",
  "user_id": "@daedric:aguiarvieira.pt",
  "age": 133243859
}
richvdh commented 1 year ago

Indeed, that is invalid. key_validity_url should be populated by sydent, in the response to /_matrix/identity/v2/store-invite. Might be worth checking http.client_http_base in your sydent config.

daedric7 commented 1 year ago

Indeed, that is invalid. key_validity_url should be populated by sydent, in the response to /_matrix/identity/v2/store-invite. Might be worth checking http.client_http_base in your sydent config.

It's set:

client_http_base = https://aguiarvieira.pt

Both in [DEFAULT] and [general]

richvdh commented 1 year ago

right, but it needs to be in an [http] section; see for example https://github.com/matrix-org/sydent/blob/2267ee2e3ab3bdfe386c4d98d9490c074e4a7c9c/matrix_is_test/launcher.py#L22-L27

(Don't get me started about the lack of documentation)

daedric7 commented 1 year ago

right, but it needs to be in an [http] section; see for example

https://github.com/matrix-org/sydent/blob/2267ee2e3ab3bdfe386c4d98d9490c074e4a7c9c/matrix_is_test/launcher.py#L22-L27

(Don't get me started about the lack of documentation)

It's alright, i understand that the documentation is... sparse and out of date. As it has been said before:

Sydent hasn't received much love

I'll do a quick test and report back.

daedric7 commented 1 year ago

Aaannnd... Problem solved.

Although i still got the random error after signig up and accepting (non existant) terms, the join sucedded.

For reference, the difference in the invite's source:

{
  "content": {
    "display_name": "tes...@aguiarviei...",
    "key_validity_url": "https://aguiarvieira.pt/_matrix/identity/v2/pubkey/isvalid",
    "public_key": "H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg",
    "public_keys": [
      {
        "key_validity_url": "https://aguiarvieira.pt/_matrix/identity/api/v1/pubkey/isvalid",
        "public_key": "H5TlGldhvLE1bU6ZtrCLuhOxB4zRhZStj65K/p7P2tg"
      },
      {
        "key_validity_url": "https://aguiarvieira.pt/_matrix/identity/api/v1/pubkey/ephemeral/isvalid",
        "public_key": "N72jNH9jYyDJ3_5FXYFqEZUtQiJj-4l9L1CqMFnQ9Do"
      }
    ]
  },
  "origin_server_ts": 1696250537363,
  "sender": "@daedric:aguiarvieira.pt",
  "state_key": "NZqkbanXMTyDLLJJacuuPZOQkQjssbFOuuNaswsXKTydAPztyVkHxcAHtgdSkYGpJVlFXkOhgxLwKQQEqsazOIstuvwLsdtkiJzMMgepKUkKKuMHyEiCBKAhSzxEptFg",
  "type": "m.room.third_party_invite",
  "unsigned": {
    "age": 106
  },
  "event_id": "$HSBqLGFR6Ll45g8ssEw0Mlhxm19Uvcwor0sZ6cj6-ug",
  "room_id": "!tnOYhXKUIldKCOOyzb:aguiarvieira.pt"
}
reivilibre commented 12 months ago

thanks for reporting back. I guess this is basically an instance of poor documentation biting people :(