Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Error fetching matrix.org:ed25519:auto from key server #6596

Closed
richvdh opened this issue Dec 24, 2019 · 6 comments
Closed

Error fetching matrix.org:ed25519:auto from key server #6596

richvdh opened this issue Dec 24, 2019 · 6 comments
Assignees
Labels
z-bug (Deprecated Label)

Comments

@richvdh
Copy link
Member

richvdh commented Dec 24, 2019

Attempts to fetch matrix.org's ed25519:auto key from the key server currently result in the following error:

Error processing response from key notary server matrix.org for origin server matrix.org: Key response is signed by key id matrix.org:ed25519:auto but that key is not present in the response

The problem is that (as per #5573), we recently rotated out the ed25519:auto key, so it now appears in the verify_keys (rather than the old_verify_keys) field in the response. However, we still sign the response with ed25519:auto, supposedly for compatibility with synapses which are configured to require that the notary response be signed with that key (which will include all those with configs predating #5374 / Synapse 1.0.0).

For reasons which I don't entirely understand, the code which handles the response to the key query (https://github.com/matrix-org/synapse/blob/v1.7.2/synapse/crypto/keyring.py#L513-L521) requires that each key used to sign the response appears in verify_keys.

Options for a fix include:

  • Un-rotate the key, making ed25519:auto the primary key again. However, everyone in the federation now believes that ed25519:auto stopped being used on the 19th December, and will reject everything generated thereafter. So this is a non-option.

  • Stop signing with ed25519:auto. This may break compatibility with Synapses configured to require that key.

  • Release a version of synapse which removes the check that all keys used for the signature be in verify_keys in the response.

  • Somehow hack the matrix.org notary server to include ed25519:auto in the verify_keys response, despite it no longer being an active key.

@richvdh
Copy link
Member Author

richvdh commented Dec 24, 2019

this is probably stopping back-pagination working in lots of places :/

@ara4n
Copy link
Member

ara4n commented Dec 24, 2019

i'd vote for either option 4 (stopgap for over christmas) or option 3 (everyone should be keeping updated anyway, although i'm a bit worried that we don't understand the key query response handling logic)

richvdh added a commit that referenced this issue Jan 3, 2020
As a notary server, when we return our own keys, include all of our signing
keys in verify_keys.

This is a workaround for #6596.
@richvdh richvdh self-assigned this Jan 3, 2020
richvdh added a commit that referenced this issue Jan 3, 2020
Lift the restriction that *all* the keys used for signing v2 key responses be
present in verify_keys.

Fixes #6596.
richvdh added a commit that referenced this issue Jan 6, 2020
* Kill off redundant SynapseRequestFactory

We already get the Site via the Channel, so there's no need for a dedicated
RequestFactory: we can just use the right constructor.

* Workaround for error when fetching notary's own key

As a notary server, when we return our own keys, include all of our signing
keys in verify_keys.

This is a workaround for #6596.
richvdh added a commit that referenced this issue Jan 6, 2020
Lift the restriction that *all* the keys used for signing v2 key responses be
present in verify_keys.

Fixes #6596.
@richvdh
Copy link
Member Author

richvdh commented Jan 6, 2020

fixed by #6625

@richvdh richvdh closed this as completed Jan 6, 2020
@richvdh
Copy link
Member Author

richvdh commented Jan 7, 2020

except that we now have a different error:

2020-01-07 10:52:44,600 - synapse.crypto.keyring - 635 - INFO - GET-74766- Requesting keys dict_items([('matrix.org', {'ed25519:a_RXGa': 1578394364600})]) from notary server matrix.org
2020-01-07 10:52:44,601 - synapse.http.matrixfederationclient - 408 - INFO - GET-74766- {POST-O-366151} [matrix.org] Sending request: POST matrix://matrix.org/_matrix/key/v2/query; timeout 60.000000s
2020-01-07 10:52:44,604 - synapse.http.federation.matrix_federation_agent - 242 - INFO - GET-74766- Connecting to matrix-federation.matrix.org.cdn.cloudflare.net:8443
2020-01-07 10:52:44,698 - synapse.http.matrixfederationclient - 440 - INFO - GET-74766- {POST-O-366151} [matrix.org] Got response headers: 200 OK
2020-01-07 10:52:44,699 - synapse.http.matrixfederationclient - 164 - INFO - GET-74766- {POST-O-366151} [matrix.org] Completed: 200 OK
2020-01-07 10:52:44,701 - synapse.crypto.keyring - 594 - ERROR - GET-74766- Unable to get key from 'matrix.org': SignatureVerifyException Unable to verify signature for matrix.org 
Capture point (most recent call last):
  File "/usr/lib/python3.5/runpy.py", line 184, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib/python3.5/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/synapse/synapse/synapse/app/homeserver.py", line 630, in <module>
    main()
  File "/opt/synapse/synapse/synapse/app/homeserver.py", line 626, in main
    run(hs)
  File "/opt/synapse/synapse/synapse/app/homeserver.py", line 617, in run
    logger=logger,
  File "/opt/synapse/synapse/synapse/app/_base.py", line 139, in start_reactor
    run()
  File "/opt/synapse/synapse/synapse/app/_base.py", line 114, in run
    run_command()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py", line 1267, in run
    self.mainLoop()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py", line 1279, in mainLoop
    self.doIteration(t)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/epollreactor.py", line 235, in doPoll
    log.callWithLogger(selectable, _drdw, selectable, fd, event)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/posixbase.py", line 614, in _doReadOrWrite
    why = selectable.doRead()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/tcp.py", line 243, in doRead
    return self._dataReceived(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/tcp.py", line 249, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/endpoints.py", line 125, in dataReceived
    return self._wrappedProtocol.dataReceived(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/protocols/tls.py", line 330, in dataReceived
    self._flushReceiveBIO()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/protocols/tls.py", line 295, in _flushReceiveBIO
    ProtocolWrapper.dataReceived(self, bytes)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/protocols/policies.py", line 120, in dataReceived
    self.wrappedProtocol.dataReceived(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 1616, in dataReceived
    self._parser.dataReceived(bytes)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 389, in dataReceived
    HTTPParser.dataReceived(self, data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/protocols/basic.py", line 579, in dataReceived
    why = self.rawDataReceived(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 302, in rawDataReceived
    self.bodyDecoder.dataReceived(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/http.py", line 1833, in dataReceived
    data = getattr(self, '_dataReceived_%s' % (self.state,))(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/http.py", line 1801, in _dataReceived_TRAILER
    self.finishCallback(data)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 454, in _finished
    self.finisher(rest)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 973, in dispatcher
    return func(*args, **kwargs)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 1570, in _finishResponse_WAITING
    self._disconnectParser(reason)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 1596, in _disconnectParser
    parser.connectionLost(reason)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 565, in connectionLost
    self.response._bodyDataFinished()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 973, in dispatcher
    return func(*args, **kwargs)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py", line 1229, in _bodyDataFinished_CONNECTED
    self._bodyProtocol.connectionLost(reason)
  File "/opt/synapse/env3/lib/python3.5/site-packages/treq/content.py", line 39, in connectionLost
    self.finished.callback(None)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/synapse/synapse/util/async_helpers.py", line 479, in success_cb
    new_d.callback(val)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1421, in _inlineCallbacks
    status.deferred.callback(getattr(e, "value", None))
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1421, in _inlineCallbacks
    status.deferred.callback(getattr(e, "value", None))
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
Traceback (most recent call last):
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'server_keys': [{'tls_fingerprints': [{'sha256': 'Pq3kW4n2StFnOFtA0PTiXIk0HZF6jwLyR8tMlaRko6I'}, {'sha256': 'mVNAmfjFleUpJseTNjU5EhJAlfl5rjb7JJPG2UeH9eY'}], 'verify_keys': {'ed25519:a_RXGa': {'key': 'l8Hft5qXKn1vfHrg3p4+W8gELQVo8N13JkluMfmn2sQ'}, 'ed25519:auto': {'key': 'Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw'}}, 'old_verify_keys': {'ed25519:auto': {'expired_ts': 1576767829750, 'key': 'Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw'}}, 'server_name': 'matrix.org', 'valid_until_ts': 1578455196929, 'signatures': {'matrix.org': {'ed25519:a_RXGa': 'slnCqa4GTIjvOiXGWqZQxveHIgNywXeZjrtDO87n4GzOHL0jYIQ+gEPtryQUOXBIznVCFuubJBuKGk3VBb8XCg', 'ed25519:auto': 'WmHAFSzD65OpmrJxIWAAOMjiGTfzMCvVxnQgk/esgEhUF8LWtfAlb1NV/Bds44MGnGnQh5txydopN3wSII8hAw'}}}]}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'server_keys': [{'tls_fingerprints': [{'sha256': 'Pq3kW4n2StFnOFtA0PTiXIk0HZF6jwLyR8tMlaRko6I'}, {'sha256': 'mVNAmfjFleUpJseTNjU5EhJAlfl5rjb7JJPG2UeH9eY'}], 'verify_keys': {'ed25519:a_RXGa': {'key': 'l8Hft5qXKn1vfHrg3p4+W8gELQVo8N13JkluMfmn2sQ'}, 'ed25519:auto': {'key': 'Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw'}}, 'old_verify_keys': {'ed25519:auto': {'expired_ts': 1576767829750, 'key': 'Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw'}}, 'server_name': 'matrix.org', 'valid_until_ts': 1578455196929, 'signatures': {'matrix.org': {'ed25519:a_RXGa': 'slnCqa4GTIjvOiXGWqZQxveHIgNywXeZjrtDO87n4GzOHL0jYIQ+gEPtryQUOXBIznVCFuubJBuKGk3VBb8XCg', 'ed25519:auto': 'WmHAFSzD65OpmrJxIWAAOMjiGTfzMCvVxnQgk/esgEhUF8LWtfAlb1NV/Bds44MGnGnQh5txydopN3wSII8hAw'}}}]}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/env3/lib/python3.5/site-packages/signedjson/sign.py", line 121, in verify_signed_json
    verify_key.verify(message, signature)
  File "/opt/synapse/env3/lib/python3.5/site-packages/nacl/signing.py", line 114, in verify
    return nacl.bindings.crypto_sign_open(smessage, self._key)
  File "/opt/synapse/env3/lib/python3.5/site-packages/nacl/bindings/crypto_sign.py", line 109, in crypto_sign_open
    raise exc.BadSignatureError("Signature was forged or corrupt")
nacl.exceptions.BadSignatureError: Signature was forged or corrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/synapse/synapse/crypto/keyring.py", line 582, in get_key
    keys_to_fetch, key_server
signedjson.sign.SignatureVerifyException: Unable to verify signature for matrix.org 
2020-01-07 10:52:44,715 - synapse.http.matrixfederationclient - 408 - INFO - GET-74766- {GET-O-366152} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/key/v2/server/ed25519%3Aa_RXGa; timeout 10.000000s
2020-01-07 10:52:44,746 - synapse.http.matrixfederationclient - 440 - INFO - GET-74766- {GET-O-366152} [matrix.org] Got response headers: 200 OK
2020-01-07 10:52:44,747 - synapse.http.matrixfederationclient - 164 - INFO - GET-74766- {GET-O-366152} [matrix.org] Completed: 200 OK
2020-01-07 10:52:44,760 - synapse.federation.transport.server - 154 - INFO - GET-74766- Request from matrix.org

@richvdh richvdh reopened this Jan 7, 2020
@richvdh
Copy link
Member Author

richvdh commented Jan 7, 2020

This happens every 24 hours or so, because matrix.org publishes its keys with a refresh interval of 24 hours (ie, the default).

It's actually not as bad as it appears, because once the lookup fails on the keyserver, it falls back to a direct lookup, which works fine. Still, it looks like the notary server is now publishing broken responses (presumably as a result of #6620), which is a thing we should fix.

@richvdh
Copy link
Member Author

richvdh commented Jan 9, 2020

hopefully fixed (again) by #6657

@richvdh richvdh closed this as completed Jan 9, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
z-bug (Deprecated Label)
Projects
None yet
Development

No branches or pull requests

3 participants