test failures with openssl 1.1.1e

matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.

https://matrix-org.github.io/synapse

Apache License 2.0

11.82k stars 2.13k forks source link

test failures with openssl 1.1.1e #7148

Closed Bubu closed 4 years ago

Bubu commented 4 years ago

Description

Steps to reproduce

run synapse 1.12.0 tests during archlinux packaging
this runs PYTHONPATH=. trial3 tests after python setup.py build
then I get the following 2 test failures

tests.test_visibility.FilterEventsForServerTestCase.test_large_room
===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/bubu/build/community/matrix-synapse/repos/community-any/src/synapse-1.12.0/tests/http/federation/test_matrix_federation_agent.py", line 411, in test_get_hostname_bad_cert
    e = self.failureResultOf(test_d, ResponseNeverReceived)
  File "/usr/lib/python3.8/site-packages/twisted/trial/_synctest.py", line 743, in failureResultOf
    self.fail(
twisted.trial.unittest.FailTest: Failure result expected on <Deferred at 0x7f59f03f50d0>, found no result instead

tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_hostname_bad_cert
===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/bubu/build/community/matrix-synapse/repos/community-any/src/synapse-1.12.0/tests/http/federation/test_matrix_federation_agent.py", line 442, in test_get_ip_address_bad_cert
    e = self.failureResultOf(test_d, ResponseNeverReceived)
  File "/usr/lib/python3.8/site-packages/twisted/trial/_synctest.py", line 743, in failureResultOf
    self.fail(
twisted.trial.unittest.FailTest: Failure result expected on <Deferred at 0x7f59f051b160>, found no result instead

tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert
-------------------------------------------------------------------------------
Ran 907 tests in 328.985s

Here's the PKGBUILD file, but this really isn't doing anything crazy. https://git.archlinux.org/svntogit/community.git/tree/trunk/PKGBUILD?h=packages/matrix-synapse

anoadragon453 commented 4 years ago

Am I to understand correctly that this is correctly breaking installing/updating Synapse on Arch Linux and derivatives?

Bubu commented 4 years ago

@anoadragon453 I'm not the maintainer, so I can't completely answer that. Packages are not required to run tests during the build process, the synapse package has historically done that though.

My take on this is, it's relatively unlikely to get updated in a timely manner before either the tests are fixed or someone who understands what's going on decides that it's okay to ignore these failures.

richvdh commented 4 years ago

@Bubu there should be some logs in a directory called _trial_temp. could you see if there is anything useful there? might also be worth setting the env var SYNAPSE_TEST_LOG_LEVEL=INFO.

Bubu commented 4 years ago

test.log after setting the env var and running only the two failing tests.

test.log

Bubu commented 4 years ago

This looks like this might be related to https://github.com/openssl/openssl/issues/11381 and thus being caused by https://github.com/openssl/openssl/commit/db943f43a60d1b5b1277e4b5317e8f288e7a0a3a

Which means it would not be related to 1.12.0 but might still be worth looking into.

anoadragon453 commented 4 years ago

It looks like the PKGBUILD may indeed be a problem.

Running the command I usually run for testing vs. the one specified in check():

~/code/synapse release-v1.12.0 *24 ?11 ❯ python -m twisted.trial tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert                                                                            🐍 env 15:51:35
tests.http.federation.test_matrix_federation_agent
  MatrixFederationAgentTests
    test_get_ip_address_bad_cert ... Signature ok
subject=
Getting CA Private Key
                                      [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.105s

PASSED (successes=1)
~/code/synapse release-v1.12.0 *24 ?11 ❯ PYTHONPATH=. trial3 tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert                                                                                🐍 env 15:51:39
tests.http.federation.test_matrix_federation_agent
  MatrixFederationAgentTests
    test_get_ip_address_bad_cert ... Signature ok
subject=
Getting CA Private Key
                                    [FAIL]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/user/code/synapse/tests/http/federation/test_matrix_federation_agent.py", line 442, in test_get_ip_address_bad_cert
    e = self.failureResultOf(test_d, ResponseNeverReceived)
  File "/usr/lib/python3.8/site-packages/twisted/trial/_synctest.py", line 743, in failureResultOf
    self.fail(
twisted.trial.unittest.FailTest: Failure result expected on <Deferred at 0x7f37d998f3d0>, found no result instead

tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert
-------------------------------------------------------------------------------
Ran 1 tests in 0.099s

FAILED (failures=1)
~/code/synapse release-v1.12.0 *24 ?11 ❯

At the moment I'm not sure why this is the case, but I'd advise to change the PKGBUILD to run through python module instead and see if that fixes things.

anoadragon453 commented 4 years ago

Also, if you do end up making the change here, adding a -j$(nproc --ignore=1) would help speed up check() execution.

a22sc commented 4 years ago

I experience a similar behavior on arch with python-twisted 19.10.0-3:

> $ python -m twisted.trial tests.http.federation.test_matrix_federation_agent
tests.http.federation.test_matrix_federation_agent
  MatrixFederationAgentTests
    test_get ... Signature ok
subject=
Getting CA Private Key
                                                          [OK]
    test_get_hostname_bad_cert ...                                       [FAIL]
    test_get_hostname_srv ...                                              [OK]
    test_get_invalid_well_known ...                                        [OK]
    test_get_ip_address ...                                                [OK]
    test_get_ip_address_bad_cert ...                                     [FAIL]
    test_get_ipv6_address ...                                              [OK]
    test_get_ipv6_address_with_port ...                                    [OK]
    test_get_no_srv_no_well_known ...                                      [OK]
    test_get_well_known ...                                                [OK]
    test_get_well_known_redirect ...                                       [OK]
    test_get_well_known_srv ...                                            [OK]
    test_get_well_known_unsigned_cert ...                                  [OK]
    test_idna_servername ...                                               [OK]
    test_idna_srv_target ...                                               [OK]
    test_srv_fallbacks ...                                                 [OK]
    test_well_known_cache ...                                              [OK]
    test_well_known_cache_with_temp_failure ...                            [OK]
  TestCachePeriodFromHeaders
    test_cache_control ...                                                 [OK]
    test_expires ...                                                       [OK]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/user/synapse/tests/http/federation/test_matrix_federation_agent.py", line 411, in test_get_hostname_bad_cert
    e = self.failureResultOf(test_d, ResponseNeverReceived)
  File "/usr/lib/python3.8/site-packages/twisted/trial/_synctest.py", line 743, in failureResultOf
    self.fail(
twisted.trial.unittest.FailTest: Failure result expected on <Deferred at 0xb3a37340>, found no result instead

tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_hostname_bad_cert
===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/user/synapse/tests/http/federation/test_matrix_federation_agent.py", line 442, in test_get_ip_address_bad_cert
    e = self.failureResultOf(test_d, ResponseNeverReceived)
  File "/usr/lib/python3.8/site-packages/twisted/trial/_synctest.py", line 743, in failureResultOf
    self.fail(
twisted.trial.unittest.FailTest: Failure result expected on <Deferred at 0xb3a10dd8>, found no result instead

tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert
-------------------------------------------------------------------------------
Ran 20 tests in 14.792s

FAILED (failures=2, successes=18)
Exception ignored in: <generator object MatrixFederationAgentTests._make_get_request at 0xb3a1f300>
Traceback (most recent call last):
  File "/home/user/synapse/tests/http/federation/test_matrix_federation_agent.py", line 167, in _make_get_request
  File "/home/user/synapse/tests/http/federation/test_matrix_federation_agent.py", line 1202, in _check_logcontext
AssertionError: Expected logcontext one@b3a1f3a8 but was sentinel
Exception ignored in: <generator object MatrixFederationAgentTests._make_get_request at 0xb39ea140>
Traceback (most recent call last):
  File "/home/user/synapse/tests/http/federation/test_matrix_federation_agent.py", line 167, in _make_get_request
  File "/home/user/synapse/tests/http/federation/test_matrix_federation_agent.py", line 1202, in _check_logcontext
AssertionError: Expected logcontext one@b39ea1e8 but was sentinel

Bubu commented 4 years ago

@anoadragon453 I get the same failure regardless of which of the two commands I'm running.

anoadragon453 commented 4 years ago

Ah, trial3 for me is using a different python environment (my global one). That's probably why.

global env:

❯ pip freeze                                                                                                                                                                                                           appdirs==1.4.3
attrs==19.3.0
Automat==20.2.0
bcrypt==3.1.7
bleach==3.1.3
canonicaljson==1.1.4
certifi==2019.11.28
cffi==1.14.0
chardet==3.0.4
constantly==15.1.0
cryptography==2.8
daemonize==2.5.0
defusedxml==0.6.0
frozendict==1.2
hyperlink==19.0.0
idna==2.9
incremental==17.5.0
Jinja2==2.11.1
jsonschema==3.2.0
lxml==4.5.0
MarkupSafe==1.1.1
mock==3.0.5
msgpack==0.6.2
netaddr==0.7.19
phonenumbers==8.12.0
Pillow==6.2.1
prometheus-client==0.7.1
pyasn1==0.4.8
pyasn1-modules==0.2.8
pycparser==2.20
Pygments==2.6.1
PyHamcrest==1.9.0
pymacaroons==0.13.0
PyNaCl==1.3.0
pyOpenSSL==19.1.0
pyrsistent==0.16.0
pysaml2==5.0.0
python-dateutil==2.8.1
pytz==2019.3
PyYAML==5.3
requests==2.23.0
requests-toolbelt==0.9.1
service-identity==18.1.0
signedjson==1.1.0
simplejson==3.17.0
six==1.14.0
sortedcontainers==2.1.0
toml==0.10.0
treq==20.3.0
Twisted==20.3.0
typing-extensions==3.7.4.1
unpaddedbase64==1.1.0
urllib3==1.25.8
webencodings==0.5.1
zope.interface==4.7.2

happy (dev) environment:

❯ pip freeze                                                                                                                                                                                                    appdirs==1.4.3
attrs==19.3.0
Automat==0.8.0
bcrypt==3.1.7
black==19.10b0
bleach==3.1.0
canonicaljson==1.1.4
certifi==2019.11.28
cffi==1.13.2
chardet==3.0.4
Click==7.0
constantly==15.1.0
cryptography==2.8
daemonize==2.5.0
defusedxml==0.6.0
docutils==0.16
entrypoints==0.3
flake8==3.7.9
frozendict==1.2
hyperlink==19.0.0
idna==2.8
incremental==17.5.0
isort==4.3.21
jeepney==0.4.3
Jinja2==2.10.3
jsonschema==3.2.0
keyring==21.2.0
lxml==4.4.2
MarkupSafe==1.1.1
-e git+git@github.com:matrix-org/synapse@88bb6c27e1ddf67ba8620eb1d856b113214e3507#egg=matrix_synapse
mccabe==0.6.1
mock==4.0.2
msgpack==0.6.2
netaddr==0.7.19
parameterized==0.7.1
pathspec==0.7.0
phonenumbers==8.11.1
Pillow==7.0.0
pkginfo==1.5.0.1
prometheus-client==0.3.1
psutil==5.7.0
pyasn1==0.4.8
pyasn1-modules==0.2.7
pycodestyle==2.5.0
pycparser==2.19
pyflakes==2.1.1
Pygments==2.6.1
PyHamcrest==1.9.0
pymacaroons==0.13.0
PyNaCl==1.3.0
pyOpenSSL==19.1.0
pyrsistent==0.15.6
pysaml2==5.0.0
python-dateutil==2.8.1
pytz==2019.3
PyYAML==5.2
readme-renderer==25.0
regex==2019.12.20
requests==2.22.0
requests-toolbelt==0.9.1
SecretStorage==3.1.2
service-identity==18.1.0
signedjson==1.1
simplejson==3.17.0
six==1.13.0
sortedcontainers==2.1.0
toml==0.10.0
towncrier==19.2.0
tqdm==4.44.1
treq==18.6.0
twine==3.1.1
Twisted==19.10.0
typed-ast==1.4.0
typing-extensions==3.7.4.1
unpaddedbase64==1.1.0
urllib3==1.25.7
webencodings==0.5.1
zope.interface==4.7.1

Currently trying to mess around with dependency versions and see if anything makes the tests pass.

anoadragon453 commented 4 years ago

Tested using the same Twisted version still has one fail and one succeed. Same results with the same matrix-synapse version.

Both environments report the same OpenSSL version in use.

openssl.py

import ssl
print(ssl.OPENSSL_VERSION)

~/code/synapse release-v1.12.0 *25 ?15 ❯ python openssl.py                                                                                                                                                                                                10s 14:21:44
OpenSSL 1.1.1e  17 Mar 2020
~/code/synapse release-v1.12.0 *25 ?15 ❯ env/bin/python openssl.py                                                                                                                                                                                            14:21:48
OpenSSL 1.1.1e  17 Mar 2020
~/code/synapse release-v1.12.0 *25 ?15 ❯ which python                                                                                                                                                                                                         14:21:51
/usr/bin/python
~/code/synapse release-v1.12.0 *25 ?15 ❯

anoadragon453 commented 4 years ago

Checking _trial_temp/test.log, I can see:

❯ cat _trial_temp/test.log                                                                                                                 14:24:57
2020-03-31 14:24:39+0100 [-] Log opened.
2020-03-31 14:24:39+0100 [-] --> tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert <--
2020-03-31 14:24:39+0100 [-] 2020-03-31 14:24:39,249 - synapse.crypto.context_factory - 178 - ERROR -  - Error during info_callback
    Traceback (most recent call last):
      File "/home/user/code/synapse/synapse/crypto/context_factory.py", line 237, in verify_context_info_cb
        verify_ip_address(ssl_connection, self._hostnameASCII)
      File "/usr/lib/python3.8/site-packages/service_identity/pyopenssl.py", line 73, in verify_ip_address
        verify_service_identity(
      File "/usr/lib/python3.8/site-packages/service_identity/_common.py", line 68, in verify_service_identity
        raise VerificationError(errors=errors)
    service_identity.exceptions.VerificationError: VerificationError(errors=[IPAddressMismatch(mismatched_id=IPAddress_ID(ip=IPv4Address('1.2.3.5')))])

    During handling of the above exception, another exception occurred:

    Traceback (most recent call last):
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 274, in _flushReceiveBIO
        bytes = self._tlsConnection.recv(2 ** 15)
      File "/usr/lib/python3.8/site-packages/OpenSSL/SSL.py", line 1809, in recv
        self._raise_ssl_error(self._ssl, result)
      File "/usr/lib/python3.8/site-packages/OpenSSL/SSL.py", line 1671, in _raise_ssl_error
        _raise_current_error()
      File "/usr/lib/python3.8/site-packages/OpenSSL/_util.py", line 54, in exception_from_error_queue
        raise exception_type(errors)
    OpenSSL.SSL.Error: [('SSL routines', 'ssl3_read_n', 'unexpected eof while reading')]

    During handling of the above exception, another exception occurred:

    Traceback (most recent call last):
      File "/home/user/code/synapse/synapse/crypto/context_factory.py", line 176, in _context_info_cb
        tls_protocol._synapse_tls_verifier.verify_context_info_cb(ssl_connection, where)
      File "/home/user/code/synapse/synapse/crypto/context_factory.py", line 243, in verify_context_info_cb
        tls_protocol.failVerification(f)
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 449, in failVerification
        self.abortConnection()
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 436, in abortConnection
        self.transport.abortConnection()
      File "/home/user/code/synapse/tests/server.py", line 418, in abortConnection
        self._protocol.connectionLost(None)
      File "/usr/lib/python3.8/site-packages/twisted/internet/endpoints.py", line 146, in connectionLost
        return self._wrappedProtocol.connectionLost(reason)
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 398, in connectionLost
        self._flushReceiveBIO()
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 292, in _flushReceiveBIO
        self._tlsShutdownFinished(failure)
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 378, in _tlsShutdownFinished
        self._flushSendBIO()
      File "/usr/lib/python3.8/site-packages/twisted/protocols/tls.py", line 257, in _flushSendBIO
        self.transport.write(bytes)
      File "/home/user/code/synapse/tests/server.py", line 452, in write
        raise Exception("Writing to disconnecting FakeTransport")
    Exception: Writing to disconnecting FakeTransport

which the failing test does not produce.

anoadragon453 commented 4 years ago

So does seem to be a problem with 1.1.1e, but why it's not happening in my dev environment is beyond me.

~/code/synapse release-v1.12.0 *25 !1 ?15 ❯ python -m twisted.trial tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert                                                                          ↵ INT 14:44:12
tests.http.federation.test_matrix_federation_agent
  MatrixFederationAgentTests
    test_get_ip_address_bad_cert ... Signature ok
subject=
Getting CA Private Key
OpenSSL 1.1.1e  17 Mar 2020
                                    [FAIL]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/user/code/synapse/tests/http/federation/test_matrix_federation_agent.py", line 446, in test_get_ip_address_bad_cert
    e = self.failureResultOf(test_d, ResponseNeverReceived)
  File "/usr/lib/python3.8/site-packages/twisted/trial/_synctest.py", line 743, in failureResultOf
    self.fail(
twisted.trial.unittest.FailTest: Failure result expected on <Deferred at 0x7f72bd91a3d0>, found no result instead

tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert
-------------------------------------------------------------------------------
Ran 1 tests in 0.111s

FAILED (failures=1)
~/code/synapse release-v1.12.0 *25 !1 ?15 ❯ env/bin/python -m twisted.trial tests.http.federation.test_matrix_federation_agent.MatrixFederationAgentTests.test_get_ip_address_bad_cert                                                                        14:44:16
tests.http.federation.test_matrix_federation_agent
  MatrixFederationAgentTests
    test_get_ip_address_bad_cert ... Signature ok
subject=
Getting CA Private Key
OpenSSL 1.1.1e  17 Mar 2020
                                      [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.103s

PASSED (successes=1)
~/code/synapse release-v1.12.0 *25 !1 ?15 ❯

Bubu commented 4 years ago

Hm. openssl 1.1.1f released which reverts that change:

 Changes between 1.1.1e and 1.1.1f [31 Mar 2020]

  *) Revert the change of EOF detection while reading in libssl to avoid
     regressions in applications depending on the current way of reporting
     the EOF. As the existing method is not fully accurate the change to
     reporting the EOF via SSL_ERROR_SSL is kept on the current development
     branch and will be present in the 3.0 release.
     [Tomas Mraz]

My tests are good again. I'll close this.