nova-compute fails with Unhandled error: TypeError: _wrap_socket_sni() got an unexpected keyword argument 'ca_certs'

[Michal Nasiadka]

In Kolla-Ansible CI we are observing those errors from 2nd of November:

Link to Zuul job list: https://zuul.openstack.org/builds?job_name=kolla-ansible-ubuntu-source&job_name=kolla-ansible-centos8-source&branch=master

Link to log: https://zuul.openstack.org/build/28d615b8c06640afae885c3ef5a2f316/log/primary/logs/kolla/nova/nova-compute.txt

2020-11-03 10:32:33.812 6 CRITICAL nova [req-d101564c-d4a7-400d-b5bc-b061c5087b1b - - - - -] Unhandled error: TypeError: _wrap_socket_sni() got an unexpected keyword argument 'ca_certs'
8 2020-11-03 10:32:33.812 6 ERROR nova Traceback (most recent call last):
9 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/bin/nova-compute", line 8, in <module>
10 2020-11-03 10:32:33.812 6 ERROR nova sys.exit(main())
11 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/cmd/compute.py", line 59, in main
12 2020-11-03 10:32:33.812 6 ERROR nova topic=compute_rpcapi.RPC_TOPIC)
13 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/service.py", line 256, in create
14 2020-11-03 10:32:33.812 6 ERROR nova periodic_interval_max=periodic_interval_max)
15 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/service.py", line 115, in __init__
16 2020-11-03 10:32:33.812 6 ERROR nova conductor_api.wait_until_ready(context.get_admin_context())
17 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/conductor/api.py", line 68, in wait_until_ready
18 2020-11-03 10:32:33.812 6 ERROR nova timeout=timeout)
19 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/baserpc.py", line 58, in ping
20 2020-11-03 10:32:33.812 6 ERROR nova return cctxt.call(context, 'ping', arg=arg_p)
21 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 179, in call
22 2020-11-03 10:32:33.812 6 ERROR nova transport_options=self.transport_options)
23 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/transport.py", line 128, in _send
24 2020-11-03 10:32:33.812 6 ERROR nova transport_options=transport_options)
25 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 654, in send
26 2020-11-03 10:32:33.812 6 ERROR nova transport_options=transport_options)
27 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 598, in _send
28 2020-11-03 10:32:33.812 6 ERROR nova msg.update({'_reply_q': self._get_reply_q()})
29 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 579, in _get_reply_q
30 2020-11-03 10:32:33.812 6 ERROR nova conn = self._get_connection(rpc_common.PURPOSE_LISTEN)
31 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 570, in _get_connection
32 2020-11-03 10:32:33.812 6 ERROR nova purpose=purpose)
33 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/common.py", line 425, in __init__
34 2020-11-03 10:32:33.812 6 ERROR nova self.connection = connection_pool.create(purpose)
35 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/pool.py", line 146, in create
36 2020-11-03 10:32:33.812 6 ERROR nova return self.connection_cls(self.conf, self.url, purpose)
37 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_rabbit.py", line 618, in __init__
38 2020-11-03 10:32:33.812 6 ERROR nova self.ensure_connection()
39 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_rabbit.py", line 735, in ensure_connection
40 2020-11-03 10:32:33.812 6 ERROR nova self.connection.ensure_connection(errback=on_error)
41 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/kombu/connection.py", line 383, in ensure_connection
42 2020-11-03 10:32:33.812 6 ERROR nova self._ensure_connection(*args, **kwargs)
43 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/kombu/connection.py", line 439, in _ensure_connection
44 2020-11-03 10:32:33.812 6 ERROR nova callback, timeout=timeout
45 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/kombu/utils/functional.py", line 325, in retry_over_time
46 2020-11-03 10:32:33.812 6 ERROR nova return fun(*args, **kwargs)
47 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/kombu/connection.py", line 866, in _connection_factory
48 2020-11-03 10:32:33.812 6 ERROR nova self._connection = self._establish_connection()
49 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/kombu/connection.py", line 801, in _establish_connection
50 2020-11-03 10:32:33.812 6 ERROR nova conn = self.transport.establish_connection()
51 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/kombu/transport/pyamqp.py", line 128, in establish_connection
52 2020-11-03 10:32:33.812 6 ERROR nova conn.connect()
53 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/amqp/connection.py", line 314, in connect
54 2020-11-03 10:32:33.812 6 ERROR nova self.transport.connect()
55 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/amqp/transport.py", line 78, in connect
56 2020-11-03 10:32:33.812 6 ERROR nova self.socket_settings, self.read_timeout, self.write_timeout,
57 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/amqp/transport.py", line 188, in _init_socket
58 2020-11-03 10:32:33.812 6 ERROR nova self._setup_transport()
59 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/amqp/transport.py", line 323, in _setup_transport
60 2020-11-03 10:32:33.812 6 ERROR nova self.sock = self._wrap_socket(self.sock, **self.sslopts)
61 2020-11-03 10:32:33.812 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/amqp/transport.py", line 330, in _wrap_socket
62 2020-11-03 10:32:33.812 6 ERROR nova return self._wrap_socket_sni(sock, **sslopts)
63 2020-11-03 10:32:33.812 6 ERROR nova TypeError: _wrap_socket_sni() got an unexpected keyword argument 'ca_certs'
64 2020-11-03 10:32:33.812 6 ERROR nova
65

[Michal Nasiadka (mnasiadka)]

Logs from docker build:
Failing containers (some packages are installed in nova-base layer, some in nova-compute):

Ubuntu
https://zuul.openstack.org/build/33bcd97f0e1947f28e3a316e64433500/log/primary/logs/build/nova-base.log
https://zuul.openstack.org/build/33bcd97f0e1947f28e3a316e64433500/log/primary/logs/build/nova-compute.log

CentOS8:
https://zuul.openstack.org/build/a1534a55fe144e02af128a169cfc55f8/log/primary/logs/build/nova-base.log
https://zuul.openstack.org/build/a1534a55fe144e02af128a169cfc55f8/log/primary/logs/build/nova-compute.log

Working containers:

Ubuntu:
https://zuul.openstack.org/build/67281bdca167472e8cedaa58bc8cdaa7/log/primary/logs/build/nova-base.log
https://zuul.openstack.org/build/67281bdca167472e8cedaa58bc8cdaa7/log/primary/logs/build/nova-compute.log

CentOS8:
https://zuul.openstack.org/build/5338eb03c8e24e91928276158006bf75/log/primary/logs/build/nova-base.log
https://zuul.openstack.org/build/5338eb03c8e24e91928276158006bf75/log/primary/logs/build/nova-compute.log

[Balazs Gibizer (balazs-gibizer)]

I looked through the last couple of day of failed job in the nova gate but none of them is due to this stack trace. I looked at the recent changes in the release repo but I see nothing obvious.

From the stack trace it nova calls down to the rpc implementation via oslo_messaging -> kombu -> pyamqp. So it seems it is an incompatibility between kombu and pyamqp

[Michal Nasiadka (mnasiadka)]

Once again, but raw links:
failed Ubuntu:
https://1213954fdcad8296313f-b58d3d982bad04bd40d81285b65fd93d.ssl.cf1.rackcdn.com/759855/2/check/kolla-ansible-ubuntu-source/33bcd97/primary/logs/build/nova-base.log
https://1213954fdcad8296313f-b58d3d982bad04bd40d81285b65fd93d.ssl.cf1.rackcdn.com/759855/2/check/kolla-ansible-ubuntu-source/33bcd97/primary/logs/build/nova-compute.log

failed CentOS:
https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_a15/759855/2/check/kolla-ansible-centos8-source/a1534a5/primary/logs/build/nova-base.log
https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_a15/759855/2/check/kolla-ansible-centos8-source/a1534a5/primary/logs/build/nova-compute.log

working Ubuntu:
https://fb4d6c24a3a28d1de5d5-e0b8e5420a715dacfb9371d5e4929e27.ssl.cf5.rackcdn.com/760533/1/check/kolla-ansible-ubuntu-source/67281bd/primary/logs/build/nova-base.log
https://fb4d6c24a3a28d1de5d5-e0b8e5420a715dacfb9371d5e4929e27.ssl.cf5.rackcdn.com/760533/1/check/kolla-ansible-ubuntu-source/67281bd/primary/logs/build/nova-compute.log

working CentOS:
https://cd1077a25f0b2d4f33d8-7883255aaad52a637069aac131629c43.ssl.cf5.rackcdn.com/760533/1/check/kolla-ansible-centos8-source/5338eb0/primary/logs/build/nova-base.log
https://cd1077a25f0b2d4f33d8-7883255aaad52a637069aac131629c43.ssl.cf5.rackcdn.com/760533/1/check/kolla-ansible-centos8-source/5338eb0/primary/logs/build/nova-compute.log

[Balazs Gibizer (balazs-gibizer)]

The first thing that I spotted is that in the working job amqp===2.6.1 and in the failed job amqp===5.0.1 . The amqp 5.0.1 was released on 20th of September and the openstack upper constraints bumped to this version on 23rd of October.

[Balazs Gibizer (balazs-gibizer)]

kombu was also bumped from 5.0.1 to 5.0.2 in upper-constraints at the same time. And the kombu 5.0.2 release updated the amqp dependency from 2.6 to 5.0.

[Balazs Gibizer (balazs-gibizer)]

The ca_certs param of _wrap_socket_sni() call was removed from amqp at [1]. Kombu is transparent for this change, but still refer to the parameter in the doc and the test. So I filed an issue for kombu about it.

So the next step in the stack is oslo_messaging and the rabbit driver there. It seems that the driver still passing ca_certs ssl parameter[3][4] to kombu and kombu passes that transparently to amqp and that fails due to [1].

So I moving this bug to oslo.messaging

[1] https://github.com/celery/py-amqp/commit/ad9697ab2eaa97e153211c82e4bad8d655e63591
[2] https://github.com/celery/kombu/issues/1266

[3] https://github.com/openstack/oslo.messaging/blob/0c4203bbdc463010d756a71bbd06720867122bcb/oslo_messaging/_drivers/impl_rabbit.py#L714
[4] https://github.com/openstack/oslo.messaging/blob/0c4203bbdc463010d756a71bbd06720867122bcb/oslo_messaging/_drivers/impl_rabbit.py#L583

[Balazs Gibizer (balazs-gibizer)]

I've pushed a requirements pin to temporary solve this issue https://review.opendev.org/#/c/761194/

[Ken Giusti (kgiusti)]

This is a py-amqp bug - the fix has been released in py-amqp version 5.0.2:

https://github.com/celery/py-amqp/pull/344

[Herve Beraud (herveberaud)]

Hello,

A related fix have been released yesterday https://github.com/celery/py-amqp/pull/344

If `ca_certs` is given the SSLContext.load_verify_locations will be called.

A new version of py-amqp will be released soon with the fix landed.

Also you can take a look to https://github.com/celery/py-amqp/issues/342#issuecomment-723910955

Hervé

[Herve Beraud (herveberaud)]

For now I think that py-amqp 5.0.2 could be blacklisted to fix the issue temporarily by waiting the fixed version.

[Herve Beraud (herveberaud)]

Sorry my previous comment is wrong 5.0.2 [1] is the fixed version [2].

[1] https://github.com/celery/py-amqp/releases
[2] https://github.com/celery/py-amqp/commit/b3f371333ff7df793628809e8abdbf43fd4391ba

[Mark Goddard (mgoddard)]

We now have kolla images with amqp 5.0.2. However, we now get a different error:

https://0976aa7a5fe989ae2839-16c03009b76be00de1a48ecc1775c29e.ssl.cf1.rackcdn.com/761519/2/check/kolla-ansible-centos8-source/564f405/primary/logs/kolla/nova/nova-compute.txt

2020-11-18 16:07:12.952 6 CRITICAL nova [req-b42dd0db-cb0b-487f-afab-b9620eb57d8e - - - - -] Unhandled error: ValueError: check_hostname needs a SSL context with either CERT_OPTIONAL or CERT_REQUIRED
2020-11-18 16:07:12.952 6 ERROR nova Traceback (most recent call last):
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/bin/nova-compute", line 8, in <module>
2020-11-18 16:07:12.952 6 ERROR nova sys.exit(main())
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/cmd/compute.py", line 59, in main
2020-11-18 16:07:12.952 6 ERROR nova topic=compute_rpcapi.RPC_TOPIC)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/service.py", line 256, in create
2020-11-18 16:07:12.952 6 ERROR nova periodic_interval_max=periodic_interval_max)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/service.py", line 115, in __init__
2020-11-18 16:07:12.952 6 ERROR nova conductor_api.wait_until_ready(context.get_admin_context())
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/conductor/api.py", line 68, in wait_until_ready
2020-11-18 16:07:12.952 6 ERROR nova timeout=timeout)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/baserpc.py", line 58, in ping
2020-11-18 16:07:12.952 6 ERROR nova return cctxt.call(context, 'ping', arg=arg_p)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 179, in call
2020-11-18 16:07:12.952 6 ERROR nova transport_options=self.transport_options)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/transport.py", line 128, in _send
2020-11-18 16:07:12.952 6 ERROR nova transport_options=transport_options)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 654, in send
2020-11-18 16:07:12.952 6 ERROR nova transport_options=transport_options)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 598, in _send
2020-11-18 16:07:12.952 6 ERROR nova msg.update({'_reply_q': self._get_reply_q()})
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 579, in _get_reply_q
2020-11-18 16:07:12.952 6 ERROR nova conn = self._get_connection(rpc_common.PURPOSE_LISTEN)
2020-11-18 16:07:12.952 6 ERROR nova File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 570, in _get_connection
2020-11-18 16:07:12.952 6 ERROR nova purpose=purpose)
2020-11-18 16:07:12.952 6 ERROR nova File ...

[Joel Capitao (jcapitao)]

In RDO, we're hitting the same issue when testing promotion of:
python-amqp-5.0.2-1.el8
python-kombu-5.0.2-1.el8
python-vine-5.0.0-2.el8

in https://review.rdoproject.org/r/#/c/31607/

https://logserver.rdoproject.org/07/31607/7/check/validate-buildsys-tags-wallaby-testing-packstack-scenario001-centos8/3b6984c/logs/weirdo-project/logs/nova/nova-compute.log.txt.gz

2021-01-21 11:44:34.298 90601 ERROR nova Traceback (most recent call last):
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/bin/nova-compute", line 10, in <module>
2021-01-21 11:44:34.298 90601 ERROR nova sys.exit(main())
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/nova/cmd/compute.py", line 59, in main
2021-01-21 11:44:34.298 90601 ERROR nova topic=compute_rpcapi.RPC_TOPIC)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/nova/service.py", line 256, in create
2021-01-21 11:44:34.298 90601 ERROR nova periodic_interval_max=periodic_interval_max)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/nova/service.py", line 115, in __init__
2021-01-21 11:44:34.298 90601 ERROR nova conductor_api.wait_until_ready(context.get_admin_context())
2021-01-21 11:44:34.298 90601 ERROR nova timeout=timeout)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/nova/baserpc.py", line 58, in ping
2021-01-21 11:44:34.298 90601 ERROR nova return cctxt.call(context, 'ping', arg=arg_p)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 179, in call
2021-01-21 11:44:34.298 90601 ERROR nova transport_options=self.transport_options)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/transport.py", line 128, in _send
2021-01-21 11:44:34.298 90601 ERROR nova transport_options=transport_options)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 654, in send
2021-01-21 11:44:34.298 90601 ERROR nova transport_options=transport_options)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 598, in _send
2021-01-21 11:44:34.298 90601 ERROR nova msg.update({'_reply_q': self._get_reply_q()})
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 579, in _get_reply_q
2021-01-21 11:44:34.298 90601 ERROR nova conn = self._get_connection(rpc_common.PURPOSE_LISTEN)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 570, in _get_connection
2021-01-21 11:44:34.298 90601 ERROR nova purpose=purpose)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/common.py", line 425, in __init__
2021-01-21 11:44:34.298 90601 ERROR nova self.connection = connection_pool.create(purpose)
2021-01-21 11:44:34.298 90601 ERROR nova File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/pool.py"...

[yatin (yatinkarel)]

https://github.com/celery/py-amqp/commit/343a00e828d9d2d33998ccaf96dca0b9417f04af should fix the check_hostname code and is included in amqp-5.0.3, which is being updated in u-c with https://review.opendev.org/c/openstack/requirements/+/771753/3/upper-constraints.txt#227