Paramiko 2.0 is incompatible with Mitaka

[eil397]

Unexpected API Error. TypeError. Code: 500. os-keypairs v2.1
nova (stable/mitaka , 98b38df57bfed3802ce60ee52e4450871fccdbfa)

Tempest tests (for example TestMinimumBasicScenario:test_minimum_basic_scenario) are failed on gate job for project openstack-ansible with such error (please find full logs [1]) :

-----------------------------
2016-07-22 18:46:07.399604 |
2016-07-22 18:46:07.399618 | Captured pythonlogging:
2016-07-22 18:46:07.399632 | ~~~~~~~~~~~~~~~~~~~~~~~
2016-07-22 18:46:07.399733 | 2016-07-22 18:45:47,861 2312 DEBUG [tempest.scenario.manager] paths: img: /opt/images/cirros-0.3.4-x86_64-disk.img, container_fomat: bare, disk_format: qcow2, properties: None, ami: /opt/images/cirros-0.3.4-x86_64-blank.img, ari: /opt/images/cirros-0.3.4-x86_64-initrd, aki: /opt/images/cirros-0.3.4-x86_64-vmlinuz
2016-07-22 18:46:07.399799 | 2016-07-22 18:45:48,513 2312 INFO [tempest.lib.common.rest_client] Request (TestMinimumBasicScenario:test_minimum_basic_scenario): 201 POST http://172.29.236.100:9292/v1/images 0.651s
2016-07-22 18:46:07.399889 | 2016-07-22 18:45:48,513 2312 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'x-image-meta-name': 'tempest-scenario-img--306818818', 'x-image-meta-container_format': 'bare', 'X-Auth-Token': '<omitted>', 'x-image-meta-disk_format': 'qcow2', 'x-image-meta-is_public': 'False'}
2016-07-22 18:46:07.399907 | Body: None
2016-07-22 18:46:07.400027 | Response - Headers: {'status': '201', 'content-length': '481', 'content-location': 'http://172.29.236.100:9292/v1/images', 'connection': 'close', 'location': 'http://172.29.236.100:9292/v1/images/5c390277-ec8d-4d82-b8d8-b8978473ecbe', 'date': 'Fri, 22 Jul 2016 18:45:48 GMT', 'content-type': 'application/json', 'x-openstack-request-id': 'req-6b3c6218-b3e6-4884-bb3c-b88c70733d0c'}
2016-07-22 18:46:07.400183 | Body: {"image": {"status": "queued", "deleted": false, "container_format": "bare", "min_ram": 0, "updated_at": "2016-07-22T18:45:48.000000", "owner": "1fbbcc542db344f394b4f1565a7e48fd", "min_disk": 0, "is_public": false, "deleted_at": null, "id": "5c390277-ec8d-4d82-b8d8-b8978473ecbe", "size": 0, "virtual_size": null, "name": "tempest-scenario-img--306818818", "checksum": null, "created_at": "2016-07-22T18:45:48.000000", "disk_format": "qcow2", "properties": {}, "protected": false}}
2016-07-22 18:46:07.400241 | 2016-07-22 18:45:48,517 2312 INFO [tempest.common.glance_http] Request: PUT http://172.29.236.100:9292/v1/images/5c390277-ec8d-4d82-b8d8-b8978473ecbe
2016-07-22 18:46:07.400359 | 2016-07-22 18:45:48,517 2312 INFO [tempest.common.glance_http] Request Headers: {'Transfer-Encoding': 'chunked', 'User-Agent': 'tempest', 'Content-Type': 'application/octet-stream', 'X-Auth-Token': 'gAAAAABXkmnbJaM7C2EMxfEELQEWlU27v4pCt_9tF_XGlYrgEu-eXvDcEclzZc2OyFnVy79Dfz_pH2gGvKveSTihW-hzV6ucHyF1JrdqwOYr6Z7ZoUe_0BQ4gOdxKZoqzSaqQKfdfrZnojq9OE9Dy11frFI59qqkk0303j3fWlFIUeV6NtrzX-s'}
2016-07-22 18:46:07.400403 | 2016-07-22 18:45:48,517 2312 DEBUG [tempest.common.glance_http] Actual Path: /v1/images/5c390277-ec8d-4d82-b8d8-b8978473ecbe
2016-07-22 18:46:07.400440 | 2016-07-22 18:45:50,721 2312 INFO [tempest.common.glance_http] Response Status: 200
2016-07-22 18:46:07.400555 | 2016-07-22 18:45:50,722 2312 INFO [tempest.common.glance_http] Response Headers: [('date', 'Fri, 22 Jul 2016 18:45:50 GMT'), ('content-length', '518'), ('etag', 'ee1eca47dc88f4879d8a229cc70a07c6'), ('content-type', 'application/json'), ('x-openstack-request-id', 'req-2e385c60-1755-4221-8325-caa98da1f760')]
2016-07-22 18:46:07.400597 | 2016-07-22 18:45:50,723 2312 DEBUG [tempest.scenario.manager] image:5c390277-ec8d-4d82-b8d8-b8978473ecbe
2016-07-22 18:46:07.400669 | 2016-07-22 18:45:52,416 2312 INFO [tempest.lib.common.rest_client] Request (TestMinimumBasicScenario:test_minimum_basic_scenario): 500 POST http://172.29.236.100:8774/v2.1/1fbbcc542db344f394b4f1565a7e48fd/os-keypairs 1.689s
2016-07-22 18:46:07.400778 | 2016-07-22 18:45:52,416 2312 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2016-07-22 18:46:07.400813 | Body: {"keypair": {"name": "tempest-TestMinimumBasicScenario-1803650811"}}
2016-07-22 18:46:07.400940 | Response - Headers: {'status': '500', 'content-length': '193', 'content-location': 'http://172.29.236.100:8774/v2.1/1fbbcc542db344f394b4f1565a7e48fd/os-keypairs', 'x-compute-request-id': 'req-9c07b4cc-2755-48f4-b10e-08553d43f6af', 'vary': 'X-OpenStack-Nova-API-Version', 'connection': 'close', 'x-openstack-nova-api-version': '2.1', 'date': 'Fri, 22 Jul 2016 18:45:52 GMT', 'content-type': 'application/json; charset=UTF-8'}
2016-07-22 18:46:07.401013 | Body: {"computeFault": {"message": "Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.\n<type 'exceptions.TypeError'>", "code": 500}}
2016-07-22 18:46:07.401086 | 2016-07-22 18:45:53,754 2312 INFO [tempest.lib.common.rest_client] Request (TestMinimumBasicScenario:_run_cleanups): 200 DELETE http://172.29.236.100:9292/v1/images/5c390277-ec8d-4d82-b8d8-b8978473ecbe 1.224s
2016-07-22 18:46:07.401162 | 2016-07-22 18:45:53,754 2312 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2016-07-22 18:46:07.401191 | Body: None
2016-07-22 18:46:07.401353 | Response - Headers: {'status': '200', 'content-length': '0', 'content-location': 'http://172.29.236.100:9292/v1/images/5c390277-ec8d-4d82-b8d8-b8978473ecbe', 'date': 'Fri, 22 Jul 2016 18:45:53 GMT', 'content-type': 'text/html; charset=UTF-8', 'connection': 'close', 'x-openstack-request-id': 'req-f5f3738e-7b31-4657-8f57-42399091f64b'}
2016-07-22 18:46:07.401385 | Body:
2016-07-22 18:46:07.401397 |
2016-07-22 18:46:07.401405 |
2016-07-22 18:46:07.401417 | Captured traceback:
2016-07-22 18:46:07.401430 | ~~~~~~~~~~~~~~~~~~~
2016-07-22 18:46:07.401448 | Traceback (most recent call last):
2016-07-22 18:46:07.401492 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/test.py", line 112, in wrapper
2016-07-22 18:46:07.401514 | return f(self, *func_args, **func_kwargs)
2016-07-22 18:46:07.401562 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/scenario/test_minimum_basic.py", line 102, in test_minimum_basic_scenario
2016-07-22 18:46:07.401581 | keypair = self.create_keypair()
2016-07-22 18:46:07.401622 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/scenario/manager.py", line 161, in create_keypair
2016-07-22 18:46:07.401643 | body = client.create_keypair(name=name)
2016-07-22 18:46:07.401690 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/lib/services/compute/keypairs_client.py", line 57, in create_keypair
2016-07-22 18:46:07.401714 | resp, body = self.post("os-keypairs", body=post_body)
2016-07-22 18:46:07.401754 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/lib/common/rest_client.py", line 259, in post
2016-07-22 18:46:07.401781 | return self.request('POST', url, extra_headers, headers, body)
2016-07-22 18:46:07.401827 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/lib/services/compute/base_compute_client.py", line 53, in request
2016-07-22 18:46:07.401849 | method, url, extra_headers, headers, body)
2016-07-22 18:46:07.401890 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/lib/common/rest_client.py", line 645, in request
2016-07-22 18:46:07.401904 | resp, resp_body)
2016-07-22 18:46:07.401947 | File "/opt/tempest_c2c90574a78c7704f06e8fac279c4f1d11365993/tempest/lib/common/rest_client.py", line 764, in _error_checker
2016-07-22 18:46:07.401961 | message=message)
2016-07-22 18:46:07.401984 | tempest.lib.exceptions.ServerFault: Got server fault
2016-07-22 18:46:07.402027 | Details: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
2016-07-22 18:46:07.402044 | <type 'exceptions.TypeError'>
2016-07-22 18:46:07.402052 |
2016-07-22 18:46:07.402059 |

logs from nova-api [2]

2016-07-22 18:45:50.866 2196 DEBUG oslo.messaging._drivers.impl_rabbit [req-9c07b4cc-2755-48f4-b10e-08553d43f6af 7a6d61ef4cd34e8a8c32a35a4c39e16f 1fbbcc542db344f394b4f1565a7e48fd - - -] Connecting to AMQP server on 172.29.237.147:5671 __init__ /openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py:539
2016-07-22 18:45:50.930 2196 DEBUG oslo.messaging._drivers.impl_rabbit [req-9c07b4cc-2755-48f4-b10e-08553d43f6af 7a6d61ef4cd34e8a8c32a35a4c39e16f 1fbbcc542db344f394b4f1565a7e48fd - - -] Connected to AMQP server on 172.29.237.147:5671 via [amqp] client __init__ /openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py:566
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions [req-9c07b4cc-2755-48f4-b10e-08553d43f6af 7a6d61ef4cd34e8a8c32a35a4c39e16f 1fbbcc542db344f394b4f1565a7e48fd - - -] Unexpected exception in API method
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 478, in wrapped
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 73, in wrapper
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 73, in wrapper
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/api/openstack/compute/keypairs.py", line 111, in create
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions return self._create(req, body)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/api/openstack/compute/keypairs.py", line 132, in _create
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions context, user_id, name, key_type)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/exception.py", line 110, in wrapped
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions payload)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions self.force_reraise()
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions six.reraise(self.type_, self.value, self.tb)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/exception.py", line 89, in wrapped
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions return f(self, context, *args, **kw)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/compute/api.py", line 4016, in create_key_pair
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions user_id, key_type)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/compute/api.py", line 4038, in _generate_key_pair
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions return crypto.generate_key_pair()
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/crypto.py", line 185, in generate_key_pair
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions key = generate_key(bits)
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions File "/openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/crypto.py", line 177, in generate_key
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions key = paramiko.RSAKey(vals=(rsa.e, rsa.n))
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions TypeError: __init__() got an unexpected keyword argument 'vals'
2016-07-22 18:45:52.373 2196 ERROR nova.api.openstack.extensions
2016-07-22 18:45:52.410 2196 INFO nova.api.openstack.wsgi [req-9c07b4cc-2755-48f4-b10e-08553d43f6af 7a6d61ef4cd34e8a8c32a35a4c39e16f 1fbbcc542db344f394b4f1565a7e48fd - - -] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.TypeError'>
2016-07-22 18:45:52.411 2196 DEBUG nova.api.openstack.wsgi [req-9c07b4cc-2755-48f4-b10e-08553d43f6af 7a6d61ef4cd34e8a8c32a35a4c39e16f 1fbbcc542db344f394b4f1565a7e48fd - - -] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.TypeError'> __call__ /openstack/venvs/nova-13.3.0/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1070
2016-07-22 18:45:52.415 2196 INFO nova.osapi_compute.wsgi.server [req-9c07b4cc-2755-48f4-b10e-08553d43f6af 7a6d61ef4cd34e8a8c32a35a4c39e16f 1fbbcc542db344f394b4f1565a7e48fd - - -] 172.29.238.213,172.29.236.100 "POST /v2.1/1fbbcc542db344f394b4f1565a7e48fd/os-keypairs HTTP/1.1" status: 500 len: 490 time: 1.6778960

[1] http://logs.openstack.org/09/342309/8/check/gate-openstack-ansible-dsvm-commit/224f9c0/console.html#_2016-07-22_18_46_07_400940
[2] http://logs.openstack.org/09/342309/8/check/gate-openstack-ansible-dsvm-commit/224f9c0/logs/aio1_nova_api_os_compute_container-e648e010/nova-api-os-compute.log

[eil397 (anton-haldin)]

It is repeatable issue.

Next gate job execution failed with same errors: http://logs.openstack.org/09/342309/8/check/gate-openstack-ansible-dsvm-commit/db750e1/console.html#_2016-07-22_21_12_12_401011

I've repeated it on my environment.

Looks like potential cause of issue can be related with some incompatibility between tempest and nova.

Tempest version: c2c90574a78c7704f06e8fac279c4f1d11365993 (git branch output[1])
Nova version: 98b38df57bfed3802ce60ee52e4450871fccdbfa (git branch output[2])

[1]
root@aio1-repo-container-4eb45849:/var/www/repo/openstackgit/tempest# git branch -v
* (detached from c2c9057) c2c9057 Merge "Remove Ceilometer tempest tests"
  master 6bf195e Merge "Fix subunit-describe-calls name of usage"

[2]
root@aio1-repo-container-4eb45849:/var/www/repo/openstackgit/nova# git branch -v
* (detached from 98b38df) 98b38df Merge "Properly clean up BDMs when _provision_instances fails" into stable/mitaka
  master 414df1e Merge "libvirt: update guest time after suspend"

[eil397 (anton-haldin)]

Cause of this issue was Paramiko 2.0 and nova (mitaka) version.

Compatibility Paramiko2.0 and nova was fixed for master (newton). https://review.openstack.org/#/c/314592

This bug report duplicates another one https://bugs.launchpad.net/nova/+bug/1585515

Is it possible to cherrypick commit to mitaka to have compatibility with Paramiko 2.0 ? I would like to do this backport, if it is possible.

[Augustina Ragwitz (auggy)]

Please provide a link to your change so we have a better idea of what you are trying to accomplish.

The fix in Newton was put in place as a temporary measure until Paramiko 2.1 comes out. I understand that the issue here is the global requirements in Mitaka mention supporting paramiko>=1.16.0 (https://github.com/openstack/nova/blob/stable/mitaka/requirements.txt) which could lead to an issue if 2.0 is the version in use. Because the full patch mentioned above is not actually a long term solution, I don't think that will likely be backported. It's possible support for 2.1 could get backported. Another option might be to put an upper bound on the version of paramiko supported.

I'm going to tag this for mitaka backport potential and gather more information before actually confirming this.

I've also updated the title to be more descriptive.

[eil397 (anton-haldin)]

Hi Augustina
thank you for your time.

I agree that it would be better to remove support of paramiko 1.6 and backport support of paramiko 2.0 to mitaka. I think it is good way to reduce list of upper-constraints.tx (https://github.com/openstack/requirements/blob/stable/mitaka/upper-constraints.txt#L235) and I would like to do it if it will be considered as good solution.

[Markus Zoeller (markus_z) (mzoeller)]

The Nova periodic stable mitaka test job installs paramiko==1.16.0
    http://logs.openstack.org/periodic-stable/periodic-nova-python27-db-mitaka/9d14b47/console.html#_2016-08-02_06_16_11_180799
This is the upper-constraint since Nov 2015
    https://github.com/openstack/requirements/commit/6bb1357b2a4347a29ca5911499b86de71b92fdc8#diff-0bdd949ed8a7fdd4f95240bd951779c8R212
This works fine.

The openstack-ansible project used paramiko>=1.16.0 and installed 2.0.1
    http://logs.openstack.org/09/342309/8/check/gate-openstack-ansible-dsvm-commit/224f9c0/console.html.gz#_2016-07-22_17_21_57_050330
    https://github.com/openstack/openstack-ansible/commit/9de9f4def3a731563da5778546e7f9f73e2c4214#diff-b4ef698db8ca845e5845c4618278f29aR9
openstack-ansible removed the requirement "paramiko>=1.6.0" later
    https://github.com/openstack/openstack-ansible/commit/b15363c#diff-b4ef698db8ca845e5845c4618278f29aL3
This however is only in openstack-ansible Newton and not in Mitaka:
    https://github.com/openstack/openstack-ansible/blob/stable/mitaka/requirements.txt#L9

Based on ^ I believe this is an issue of the openstack-ansible project which
doesn't cap the upper-constraint of paramiko in its stable/mitaka branch.
I don't see the need to backport anything to Nova's stable/mitaka branch.
I leave this as "incomplete" to get a second pair of eyes from auggy.

[Jesse Pretorius (jesse-pretorius)]

This is indeed related directly to a bug which was discovered and solved recently. OpenStac-Ansible was not appropriately applying upper-constraints during the repo build process. This was fixed in https://review.openstack.org/346386 (that's the Mitaka backport) and this fix will be released with 13.3.1 due to the SHA bump ( https://review.openstack.org/349535 ) including that fix.

[Markus Zoeller (markus_z) (mzoeller)]

@Jesse: Thanks for double-checking.