Tests are broken

[tiran]

• test_logging_info fails
• I'm seeing a couple of error messages in stderr that do not look correct.

$ tox -e py27
GLOB sdist-make: /home/heimes/dev/redhat/custodia/setup.py
py27 inst-nodeps: /home/heimes/dev/redhat/custodia/.tox/dist/custodia-0.6.dev1.zip
py27 installed: asn1crypto==0.23.0,attrs==17.3.0,certifi==2017.11.5,cffi==1.11.2,chardet==3.0.4,configparser==3.5.0,coverage==4.4.2,cryptography==2.1.4,custodia==0.6.dev1,decorator==4.1.2,dnspython==1.15.0,enum34==1.1.6,funcsigs==1.0.2,gssapi==1.3.0,idna==2.6,ipaclient==4.6.2,ipaddress==1.0.18,ipalib==4.6.2,ipaplatform==4.6.2,ipapython==4.6.2,jwcrypto==0.4.2,mock==2.0.0,netaddr==0.7.19,netifaces==0.10.6,pbr==3.1.1,pluggy==0.6.0,py==1.5.2,pyasn1==0.4.2,pyasn1-modules==0.2.1,pycparser==2.18,pytest==3.3.1,python-etcd==0.4.5,python-ldap==3.0.0b2,qrcode==5.3,requests==2.18.4,six==1.11.0,urllib3==1.22
py27 runtests: PYTHONHASHSEED='1142325546'
py27 runtests: commands[0] | /home/heimes/dev/redhat/custodia/.tox/py27/bin/python -m coverage run --parallel -m pytest --capture=no --strict
================================================================ test session starts ================================================================
platform linux2 -- Python 2.7.14, pytest-3.3.1, py-1.5.2, pluggy-0.6.0
rootdir: /home/heimes/dev/redhat/custodia, inifile: tox.ini
collected 161 items                                                                                                                                 

tests/test_authenticators.py ..                                                                                                               [  1%]
tests/test_cli.py .....                                                                                                                       [  4%]
tests/test_custodia.py ...........................................                                                                            [ 31%]
tests/test_httpd.py server.py                  133 ERROR    Failed to create a SSLContext for TLS server: [Errno 2] No such file or directory
.                                                                                                                         [ 31%]
tests/test_ipa.py ........................                                                                                                    [ 46%]
tests/test_message_kem.py ....                                                                                                                [ 49%]
tests/test_misc.py .log.py                      74 ERROR    some message
Traceback (most recent call last):
  File "/home/heimes/dev/redhat/custodia/tests/test_misc.py", line 43, in test_logging_info
    raise ValueError('testmsg')
ValueError: testmsg
Flog.py                      74 ERROR    some message
Traceback (most recent call last):
  File "/home/heimes/dev/redhat/custodia/tests/test_misc.py", line 57, in test_logging_debug
    raise ValueError('testmsg with stack')
ValueError: testmsg with stack
.                                                                                                                        [ 50%]
tests/test_plugins.py ....                                                                                                                    [ 53%]
tests/test_secrets.py ............log.py                      64 ERROR    Set: Key already exist
Traceback (most recent call last):
  File "/home/heimes/dev/redhat/custodia/.tox/py27/lib/python2.7/site-packages/custodia/secrets.py", line 345, in _int_set_key
    ok = self.root.store.set(key, msg.payload)
  File "/home/heimes/dev/redhat/custodia/.tox/py27/lib/python2.7/site-packages/custodia/store/sqlite.py", line 68, in set
    raise CSStoreExists(str(err))
CSStoreExists: UNIQUE constraint failed: CustodiaSecrets.key
......................                                                                                      [ 74%]
tests/test_server.py ....                                                                                                                     [ 77%]
tests/test_store.py encgen.py                   74 ERROR    Error parsing key key: ['InvalidJWEData(\'No recipient matched the provided key["Failed: [InvalidSignature(\\\'Failed to verify MAC\\\',)]"]\',)']
...                                                                                                                       [ 78%]
tests/test_store_sqlite.py ...........                                                                                                        [ 85%]
tests/functional/test_basics.py ...                                                                                                           [ 87%]
tests/functional/test_container.py .........                                                                                                  [ 93%]
tests/functional/test_key.py ...........                                                                                                      [100%]

===================================================================== FAILURES ======================================================================
_________________________________________________________________ test_logging_info _________________________________________________________________

loghandler = <logging.handlers.BufferingHandler object at 0x7fef32cbf7d0>

    def test_logging_info(loghandler):
        testlogger = log.getLogger('custodia.test')
        assert testlogger.getEffectiveLevel() == logging.INFO
        try:
            raise ValueError('testmsg')
        except ValueError:
            testlogger.exception('some message')
        assert len(loghandler.buffer) == 1
        msg = loghandler.format(loghandler.buffer[0])
        loghandler.flush()
>       assert msg.endswith('some message (ValueError: testmsg)')
E       assert False
E        +  where False = <built-in method endswith of str object at 0x7fef33f8a6f0>('some message (ValueError: testmsg)')
E        +    where <built-in method endswith of str object at 0x7fef33f8a6f0> = '2017-12-13 12:24:58 - test                             - some message\nTraceback (most recent call last):\n  File "/h...at/custodia/tests/test_misc.py", line 43, in test_logging_info\n    raise ValueError(\'testmsg\')\nValueError: testmsg'.endswith

tests/test_misc.py:49: AssertionError
----------------------------------------------------------------- Captured log call -----------------------------------------------------------------
log.py                      74 ERROR    some message
Traceback (most recent call last):
  File "/home/heimes/dev/redhat/custodia/tests/test_misc.py", line 43, in test_logging_info
    raise ValueError('testmsg')
ValueError: testmsg
======================================================= 1 failed, 160 passed in 17.51 seconds =======================================================
ERROR: InvocationError: '/home/heimes/dev/redhat/custodia/.tox/py27/bin/python -m coverage run --parallel -m pytest --capture=no --strict'
______________________________________________________________________ summary ______________________________________________________________________
ERROR:   py27: commands failed

[simo5]

I think for some reason recent openssl doesn't like the certs we have in the tests/ca directory. Unclear why, can you help debug that ?

[tiran]

The cert warnings were a red herring. pytest has a new plugin to intercept logging calls. The same plugin also installs a handler that prints all errors on stdout. Outputs like Failed to create a SSLContext are from tests that cover error cases.

All issues have been addressed in https://github.com/latchset/custodia/pull/236