search

matrix-org / sydent

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

SignatureVerifyException on Unbind threepids #512

Closed Cyberes closed 2 years ago

Cyberes commented 2 years ago

I'm unable to remove my threepid email address from my identity server. Sydent throws SignatureVerifyException in /sydent/hs_federation/verifier.py at signedjson.sign.verify_signed_json()

I run my homeserver on matrix.example.com and have both SRV records and the following in my nginx config to make the accounts show up as example.com. federationtester.matrix.org says my server passes all tests. I don't have port 8448 open.

This is a signing error but everything works up until the signedjson.sign.verify_signed_json(). The federation tester says all parts of the signed message are valid and I can join federated servers and others can join my federated rooms/spaces.

Everything else is working as it should so I really don't know what else to do here.

DMRobertson commented 2 years ago

Sydent throws SignatureVerifyException in /sydent/hs_federation/verifier.py at signedjson.sign.verify_signed_json()

Could we have the full traceback and any nearby logs please? Can you also please confirm which version of Sydent you're running?

Cyberes commented 2 years ago

How do I get a traceback? There's no error thrown, I tracked the 401: Unauthorized status to that line.

I'm on version 2.5.1

Sydent Logs: I start the server, share my email, then shut the server down.

2022-03-17 05:25:39,678 - __main__ - 114 - INFO - Starting Sydent server
2022-03-17 05:25:39,678 - sydent.db.sqlitedb - 32 - INFO - Using DB file sydent.db
2022-03-17 05:25:39,680 - sydent.http.httpcommon - 52 - WARNING - No HTTPS private key / cert found: not starting replication server or doing replication pushes
2022-03-17 05:25:39,681 - sydent.http.httpserver - 144 - INFO - Starting Client API HTTP server on :::8090
2022-03-17 05:25:39,682 - twisted - 147 - INFO - Site starting on 8090
2022-03-17 05:25:39,682 - twisted - 147 - INFO - Starting factory <twisted.web.server.Site object at 0x7f737ab757f0>
2022-03-17 05:25:39,682 - sydent.http.httpserver - 158 - INFO - Starting Internal API HTTP server on localhost:8091
2022-03-17 05:25:39,683 - twisted - 147 - INFO - Site starting on 8091
2022-03-17 05:25:39,683 - twisted - 147 - INFO - Starting factory <twisted.web.server.Site object at 0x7f737ab1ac70>
2022-03-17 05:25:42,575 - twisted - 147 - INFO - "::1" - - [17/Mar/2022:05:25:41 +0000] "OPTIONS /_matrix/identity/v2/account HTTP/1.0" 200 - "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:42,718 - twisted - 147 - INFO - "::ffff:127.0.0.1" - - [17/Mar/2022:05:25:42 +0000] "GET /_matrix/identity/v2/account HTTP/1.0" 200 33 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:42,867 - twisted - 147 - INFO - "::1" - - [17/Mar/2022:05:25:42 +0000] "GET /_matrix/identity/v2/terms HTTP/1.0" 200 270 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:43,009 - twisted - 147 - INFO - "::ffff:127.0.0.1" - - [17/Mar/2022:05:25:42 +0000] "OPTIONS /_matrix/identity/v2/validate/email/requestToken HTTP/1.0" 200 - "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:43,158 - sydent.validators.emailvalidator - 91 - INFO - Attempting to mail code Y3ufhaDhcYS7sOwBTvAN2yyxgg9k2EJF (nextLink: None) to user@whatever.com
2022-03-17 05:25:43,164 - sydent.util.emailutils - 97 - INFO - Sending mail to user@whatever.com with mail server: smtp.emailhost.com
2022-03-17 05:25:44,268 - twisted - 147 - INFO - "::1" - - [17/Mar/2022:05:25:42 +0000] "POST /_matrix/identity/v2/validate/email/requestToken HTTP/1.0" 200 20 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:50,455 - sydent.validators.common - 62 - INFO - Setting session 965055592 as validated
2022-03-17 05:25:50,458 - twisted - 147 - INFO - "::ffff:127.0.0.1" - - [17/Mar/2022:05:25:50 +0000] "GET /_matrix/identity/api/v1/validate/email/submitToken?token=Y3ufhaDhcYS7sOwBTvAN2yyxgg9k2EJF&client_secret=0iOjNWU9499oJlmZmyNY13sij2KSUeto&sid=965055592 HTTP/1.0" 200 183 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:97.0) Gecko/20100101 Firefox/97.0"
2022-03-17 05:25:52,829 - twisted - 147 - INFO - "::1" - - [17/Mar/2022:05:25:52 +0000] "OPTIONS /_matrix/identity/v2/account HTTP/1.0" 200 - "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:52,976 - twisted - 147 - INFO - "::ffff:127.0.0.1" - - [17/Mar/2022:05:25:52 +0000] "GET /_matrix/identity/v2/account HTTP/1.0" 200 33 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:53,123 - twisted - 147 - INFO - "::1" - - [17/Mar/2022:05:25:52 +0000] "GET /_matrix/identity/v2/terms HTTP/1.0" 200 270 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36"
2022-03-17 05:25:53,290 - sydent.threepid.bind - 167 - INFO - Making bind callback to: matrix://example.com/_matrix/federation/v1/3pid/onbind
2022-03-17 05:25:53,291 - sydent.http.httpclient - 127 - DEBUG - HTTP POST b'{"medium": "email", "address": "user@whatever.com", "mxid": "@user:example.com", "ts": 1647494753285, "not_before": 1647494753285, "not_after": 4801094753285, "signatures": {"example.com": {"ed25519:0": "Snm3+KqfCvQw5GGPD+4A5E0mAbD0r4yIbN38lX1YjPw0Kns3iPYgLb5IcdgXdWzUc0TOaTmjgypit5u/GESCBQ"}}}' -> matrix://example.com/_matrix/federation/v1/3pid/onbind
2022-03-17 05:25:53,291 - sydent.http.matrixfederationagent - 339 - INFO - Fetching https://example.com/.well-known/matrix/server
2022-03-17 05:25:53,300 - twisted - 147 - INFO - "::ffff:127.0.0.1" - - [17/Mar/2022:05:25:53 +0000] "POST /_matrix/identity/v2/3pid/bind HTTP/1.0" 200 293 "-" "Synapse/1.54.0"
2022-03-17 05:25:53,337 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f737aae21f0>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f737ab49130>)
2022-03-17 05:25:53,700 - sydent.http.matrixfederationagent - 348 - INFO - Response from .well-known: {'m.server': 'matrix.example.com:443'}
2022-03-17 05:25:53,707 - sydent.http.matrixfederationagent - 389 - INFO - Endpoint created with b'matrix.example.com':443
2022-03-17 05:25:53,707 - sydent.http.matrixfederationagent - 394 - INFO - Connecting to matrix.example.com:443
2022-03-17 05:25:53,709 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f737aae2ee0>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f737aae6fd0>)
2022-03-17 05:25:53,731 - sydent.threepid.bind - 183 - INFO - Successfully notified on bind for @user:example.com
2022-03-17 05:25:53,731 - sydent.threepid.bind - 193 - INFO - Successfully deleted invite for user@whatever.com from the store
2022-03-17 05:26:03,577 - sydent.http.httpclient - 56 - DEBUG - HTTP GET matrix://example.com/_matrix/key/v2/server/
2022-03-17 05:26:03,585 - sydent.http.matrixfederationagent - 389 - INFO - Endpoint created with b'matrix.example.com':443
2022-03-17 05:26:03,585 - sydent.http.matrixfederationagent - 394 - INFO - Connecting to matrix.example.com:443
2022-03-17 05:26:03,586 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f737aaec280>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f737a26a0d0>)
2022-03-17 05:26:03,609 - sydent.hs_federation.verifier - 130 - INFO - Got keys for example.com: caching until 1647577689634
2022-03-17 05:26:03,609 - sydent.hs_federation.verifier - 175 - INFO - verifying sig from key 'ed25519:a_CmRQ'
2022-03-17 05:26:03,609 - twisted - 147 - INFO - "::1" - - [17/Mar/2022:05:26:03 +0000] "POST /_matrix/identity/api/v1/3pid/unbind HTTP/1.0" 401 156 "-" "Synapse/1.54.0"
^C2022-03-17 05:26:21,828 - twisted - 147 - INFO - Received SIGINT, shutting down.
2022-03-17 05:26:21,829 - twisted - 147 - INFO - Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f737aae21f0>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f737ab49130>)
2022-03-17 05:26:21,829 - twisted - 147 - INFO - Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f737aaec280>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f737a26a0d0>)
2022-03-17 05:26:21,830 - twisted - 147 - INFO - Stopping factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7f737aae2ee0>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7f737aae6fd0>)
2022-03-17 05:26:21,830 - twisted - 147 - INFO - (TCP Port 8091 Closed)
2022-03-17 05:26:21,830 - twisted - 147 - INFO - Stopping factory <twisted.web.server.Site object at 0x7f737ab1ac70>
2022-03-17 05:26:21,830 - twisted - 147 - INFO - (TCP Port 8090 Closed)
2022-03-17 05:26:21,830 - twisted - 147 - INFO - Stopping factory <twisted.web.server.Site object at 0x7f737ab757f0>
2022-03-17 05:26:21,831 - twisted - 147 - INFO - Main loop terminated.

Synapse Logs:

2022-03-17 05:30:04,167 - synapse.http.client - 446 - INFO - POST-107520 - Received response to POST https://sydent.example.com/_matrix/identity/api/v1/3pid/unbind: 401
2022-03-17 05:30:04,167 - synapse.handlers.identity - 336 - ERROR - POST-107520 - Failed to unbind threepid on identity server: 401: Unauthorized
2022-03-17 05:30:04,167 - synapse.http.server - 95 - INFO - POST-107520 - <XForwardedForRequest at 0x7fc08f23aa90 method='POST' uri='/_matrix/client/r0/account/3pid/unbind' clientproto='HTTP/1.0' site='8008'> SynapseError: 500 - Failed to contact identity server
2022-03-17 05:30:04,168 - synapse.access.http.8008 - 427 - INFO - POST-107520 - 192.168.1.190 - 8008 - {@user:example.com} Processed request: 0.008sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 67B 500 "POST /_matrix/client/r0/account/3pid/unbind HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.6 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36" [0 dbevts]
reivilibre commented 2 years ago

Hi!

Is your homeserver using the ed25519:a_CmRQ signing key (check your homeserver configuration)? Maybe you can share the non-sensitive part of your Sydent configuration as well?

Is it possible for you to share your server name so I can have a look around? It's quite hard to diagnose without it.

Thanks

Cyberes commented 2 years ago

Yeah, hit me up at @w5d33xzsy9m7vn6v:matrix.org and we can go from there.

Cyberes commented 2 years ago

In our dm, I ran reivilibre's custom branch rei/debug/keyverification to get some more info into the logs.

2022-03-17 22:13:14,078 - sydent.hs_federation.verifier - 167 - DEBUG - Wanting to verify request: SignedMatrixRequest(method=b'POST', uri=b'/_matrix/identity/api/v1/3pid/unbind', destination_is='example.com', signatures={'example.com': {'ed25519:a_CmRQ': 'xxx'}}, origin='example.com', content={'mxid': '@sydent-test-3:example.com', 'threepid': {'address': 'qsddssad@example.com', 'medium': 'email'}})
2022-03-17 22:13:14,078 - sydent.hs_federation.verifier - 168 - DEBUG - Considering signatures {'ed25519:a_CmRQ': 'xxx'} from example.com
2022-03-17 22:13:14,078 - sydent.http.httpclient - 56 - DEBUG - HTTP GET matrix://example.com/_matrix/key/v2/server/
2022-03-17 22:13:14,086 - sydent.http.matrixfederationagent - 391 - INFO - Endpoint created with b'matrix.example.com':443
2022-03-17 22:13:14,086 - sydent.http.matrixfederationagent - 396 - INFO - Connecting to matrix.example.com:443
2022-03-17 22:13:14,087 - twisted - 147 - INFO - Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x7ff667ca3b80>, <twisted.internet.endpoints._WrapperEndpoint object at 0x7ff667c52580>)
2022-03-17 22:13:14,109 - sydent.hs_federation.verifier - 130 - INFO - Got keys for example.com: caching until 1647624652003
2022-03-17 22:13:14,109 - sydent.hs_federation.verifier - 171 - DEBUG - Found keys {'ed25519:a_CmRQ': {'key': 'xxx'}} for server example.com
2022-03-17 22:13:14,110 - sydent.hs_federation.verifier - 179 - INFO - verifying sig from key 'ed25519:a_CmRQ'
2022-03-17 22:13:14,110 - sydent.hs_federation.verifier - 181 - DEBUG - Dict payload is {'method': b'POST', 'uri': b'/_matrix/identity/api/v1/3pid/unbind', 'destination_is': 'example.com', 'signatures': {'example.com': {'ed25519:a_CmRQ': 'xxx'}}, 'origin': 'example.com', 'content': {'mxid': '@sydent-test-3:example.com', 'threepid': {'address': 'qsddssad@example.com', 'medium': 'email'}}}
2022-03-17 22:13:14,110 - sydent.hs_federation.verifier - 193 - INFO - Failed to verify sig from key 'ed25519:a_CmRQ': SignatureVerifyException("Unable to verify signature for example.com: <class 'nacl.exceptions.BadSignatureError'> Signature was forged or corrupt")

reivilibre's conclusion was this:

It thinks it's forged or corrupt... that will be difficult to track down

richvdh commented 2 years ago

I'm not sure if it's the case here, but a common cause for failure to validate the signature on federation requests is an incorrect reverse-proxy setup - in particular, including a path after the host:port in a proxy_pass line: see the documentation at https://matrix-org.github.io/synapse/latest/reverse_proxy.html#nginx (in particular the comments next to proxy_pass).

Cyberes commented 2 years ago

I've verified I don't have the slash after the host:port on any of my nginx configs. Just to give you all the info, here's my proxy setup:

  1. Nginx edge server. All web requests are made to this server then proxied to the destination.
  2. The destination server (Sydent and Synapse, on different hosts) have another nginx proxy to encrypt the Synapse/Sydent server traffic to the edge server.

I've been suspicious this problem has something to do reverse proxies. Would you like me to share all my nginx configs so you can verify they're all correct?

richvdh commented 2 years ago

If you don't mind sharing your nginx configuration, then I'd be happy to check for any obvious problems.

However, I suspect I see the problem now. In your synapse log snippet:

2022-03-17 05:30:04,167 - synapse.http.client - 446 - INFO - POST-107520 - Received response to POST https://sydent.example.com/_matrix/identity/api/v1/3pid/unbind: 401

... which is to say that Synapse thinks it is connecting to a server called sydent.example.com. However, in your sydent logs:

2022-03-17 22:13:14,078 - sydent.hs_federation.verifier - 167 - DEBUG - Wanting to verify request: SignedMatrixRequest(method=b'POST', uri=b'/_matrix/identity/api/v1/3pid/unbind', destination_is='example.com', signatures={'example.com': {'ed25519:a_CmRQ': 'xxx'}}, origin='example.com', content={'mxid': '@sydent-test-3:example.com', 'threepid': {'address': 'qsddssad@example.com', 'medium': 'email'}})

... note in particular, destination_is='example.com', which means that Sydent itself thinks it is called example.com.

The mismatch will cause the signature verification to fail. In other words, you need to decide if your identity server is called sydent.example.com or example.com, and stick to it.

reivilibre commented 2 years ago

which is to say that Synapse thinks it is connecting to a server called sydent.example.com. However, in your sydent logs:

2022-03-17 22:13:14,078 - sydent.hs_federation.verifier - 167 - DEBUG - Wanting to verify request: SignedMatrixRequest(method=b'POST', uri=b'/_matrix/identity/api/v1/3pid/unbind', destination_is='example.com', signatures={'example.com': {'ed25519:a_CmRQ': 'xxx'}}, origin='example.com', content={'mxid': '@sydent-test-3:example.com', 'threepid': {'address': 'qsddssad@example.com', 'medium': 'email'}})

... note in particular, destination_is='example.com', which means that Sydent itself thinks it is called example.com.

Using the payloads and verification keys you sent me in DM, this above is indeed the problem. The signature verification works if destination_is is sydent.example.com (not example.com as was configured on your server).

(Will close since I think this is resolved; if it still doesn't work after that then the issue can be reopened)

Cyberes commented 2 years ago

I see that I indeed set server.name in the Sydent config to example.com rather than sydent.example.com. When I configured it I wasn't sure if server.name was supposed to be the Synapse's server name (which would be example.com) or Sydent's host. Can the configuration docs be updated to include a little snippet about this distinction?

richvdh commented 2 years ago

Can the configuration docs be updated to include a little snippet about this distinction?

We'd welcome pull requests improving the documentation (though this is far from the only problem - see #101)