barbican scenario002 tests fail with urllib3.exceptions.ProtocolError: ('Connection aborted.', BadStatusLine("''",))

[Alex Schultz]

I've seen this a few times in the gate and in check where the scenario002 tempest jobs fail with connection issues when running the barbican tests.

http://logs.openstack.org/53/502553/5/check/tripleo-ci-centos-7-scenario002-multinode-oooq-container/7b65eb1/logs/undercloud/home/zuul/tempest/tempest.html.gz

ft1.1: barbican_tempest_plugin.tests.scenario.test_volume_encryption.VolumeEncryptionTest.test_encrypted_cinder_volumes_cryptsetup[compute,id-cbc752ed-b716-4727-910f-956ccf965723,image,volume]_StringException: pythonlogging:'': {{{2017-12-18 18:01:27,566 14713 DEBUG [barbican_tempest_plugin.tests.scenario.barbican_manager] Uploading certificate to barbican}}}

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/barbican_tempest_plugin/tests/scenario/barbican_manager.py", line 55, in setUp
    self.signing_certificate
  File "/usr/lib/python2.7/site-packages/barbican_tempest_plugin/tests/scenario/barbican_manager.py", line 127, in _store_cert
    payload=cert_b64
  File "/usr/lib/python2.7/site-packages/barbican_tempest_plugin/services/key_manager/json/secret_client.py", line 37, in create_secret
    resp, body = self.post("v1/secrets", body)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 279, in post
    return self.request('POST', url, extra_headers, headers, body, chunked)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 653, in request
    body=body, chunked=chunked)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 549, in _request
    chunked=chunked
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 582, in raw_request
    body=body, chunked=chunked)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/http.py", line 100, in request
    *args, **new_kwargs)
  File "/usr/lib/python2.7/site-packages/urllib3/request.py", line 70, in request
    **urlopen_kw)
  File "/usr/lib/python2.7/site-packages/urllib3/request.py", line 148, in request_encode_body
    return self.urlopen(method, url, **extra_kw)
  File "/usr/lib/python2.7/site-packages/urllib3/poolmanager.py", line 321, in urlopen
    response = conn.urlopen(method, u.request_uri, **kw)
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 649, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/lib/python2.7/site-packages/urllib3/util/retry.py", line 357, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 600, in urlopen
    chunked=chunked)
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 379, in _make_request
    httplib_response = conn.getresponse(buffering=True)
  File "/usr/lib64/python2.7/httplib.py", line 1089, in getresponse
    response.begin()
  File "/usr/lib64/python2.7/httplib.py", line 444, in begin
    version, status, reason = self._read_status()
  File "/usr/lib64/python2.7/httplib.py", line 408, in _read_status
    raise BadStatusLine(line)
urllib3.exceptions.ProtocolError: ('Connection aborted.', BadStatusLine("''",))

[Alex Schultz (alex-schultz)]

Should be noted that the cause of this error was actually a DBDeadlock in barbican-api

http://logs.openstack.org/53/502553/5/check/tripleo-ci-centos-7-scenario002-multinode-oooq-container/7b65eb1/logs/subnode-2/var/log/containers/httpd/barbican-api/barbican_wsgi_main_error.log.txt.gz

[Mon Dec 18 17:47:23.689462 2017] [:error] [pid 25] [remote 192.168.24.3:28] DBDeadlock: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'INSERT INTO secret_stores (id, created_at, updated_at, deleted_at, deleted, status, store_plugin, crypto_plugin, global_default, name) VALUES (%(id)s, %(created_at)s, %(updated_at)s, %(deleted_at)s, %(deleted)s, %(status)s, %(store_plugin)s, %(crypto_plugin)s, %(global_default)s, %(name)s)'] [parameters: {'status': 'ACTIVE', 'crypto_plugin': 'simple_crypto', 'deleted_at': None, 'name': 'Software Only Crypto', 'deleted': 0, 'global_default': 1, 'created_at': datetime.datetime(2017, 12, 18, 17, 46, 32, 468686), 'updated_at': datetime.datetime(2017, 12, 18, 17, 46, 32, 468686), 'store_plugin': 'store_crypto', 'id': '33f2e059-e932-42b3-a2fa-c6e6951dc8a1'}]

[Alex Schultz (alex-schultz)]

Proposed fix https://review.openstack.org/529126

[wes hayutin (weshayutin)]

Adding alert for general awareness this is failing in the ooo gate jobs, and it's also failing in promotion jobs so added promotion blocker

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/529126
Committed: https://git.openstack.org/cgit/openstack/barbican/commit/?id=0539a28ee95479a707b7dc3da635308a682e2ecc
Submitter: Zuul
Branch: master

commit 0539a28ee95479a707b7dc3da635308a682e2ecc
Author: Ade Lee <email address hidden>
Date: Tue Dec 19 12:21:22 2017 -0500

    Ensure only api app initializes secret store

    Right now, the multiple secret store initialization code is run
    whenever the db is initialized - whether it be running the clean
    db script, starting the worker, starting the keystone listener
    or manage db script. This periodically causes deadlocks when
    the worker,listener and app are started soon after each other.

    Its not altogether clear why the deadlock happens, but the only
    table that is being written to is the secret_store table, which
    has no foreign keys etc. In any case, though, it was never the
    intention that anything other than the app itself initialize the
    secret stores from its config file.

    This patch makes sure that happens.

    Change-Id: I711b91b19b9d65260a21b41d6f9e18b9e282138a
    Closes-bug: 1738863

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/barbican 6.0.0.0b3 development milestone.