legacy-tempest-dsvm-full-devstack-plugin-ceph job failing

[Dr. Jens Harbott]

Seems to be failing 100% since a couple of weeks, example http://logs.openstack.org/86/547986/9/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/cd4a858/

The failure is in keystone starting, seems completely unrelated to the ceph setup, so no idea what causes this yet.

Failure from keystone log:

Apr 17 07:39:54.068515 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: CRITICAL keystone [-] Unhandled error: ImportError: No module named urlmap
Apr 17 07:39:54.068936 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone Traceback (most recent call last):
Apr 17 07:39:54.069261 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/bin/keystone-wsgi-public", line 54, in <module>
Apr 17 07:39:54.069557 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone application = initialize_public_application()
Apr 17 07:39:54.069848 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/opt/stack/new/keystone/keystone/server/wsgi.py", line 134, in initialize_public_application
Apr 17 07:39:54.070139 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone config_files=_get_config_files())
Apr 17 07:39:54.070452 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/opt/stack/new/keystone/keystone/server/wsgi.py", line 66, in initialize_application
Apr 17 07:39:54.070742 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone startup_application_fn=loadapp)
Apr 17 07:39:54.071035 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/opt/stack/new/keystone/keystone/server/common.py", line 48, in setup_backends
Apr 17 07:39:54.071327 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone res = startup_application_fn()
Apr 17 07:39:54.071617 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/opt/stack/new/keystone/keystone/server/wsgi.py", line 63, in loadapp
Apr 17 07:39:54.071908 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone 'config:%s' % find_paste_config(), name)
Apr 17 07:39:54.072237 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/opt/stack/new/keystone/keystone/version/service.py", line 51, in loadapp
Apr 17 07:39:54.072534 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone controllers.latest_app = deploy.loadapp(conf, name=name)
Apr 17 07:39:54.072839 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 247, in loadapp
Apr 17 07:39:54.073146 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone return loadobj(APP, uri, name=name, **kw)
Apr 17 07:39:54.073504 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 271, in loadobj
Apr 17 07:39:54.073795 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone global_conf=global_conf)
Apr 17 07:39:54.074086 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 296, in loadcontext
Apr 17 07:39:54.074377 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone global_conf=global_conf)
Apr 17 07:39:54.075527 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 320, in _loadconfig
Apr 17 07:39:54.075863 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone return loader.get_context(object_type, name, global_conf)
Apr 17 07:39:54.076181 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 454, in get_context
Apr 17 07:39:54.076473 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone section)
Apr 17 07:39:54.076764 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 476, in _context_from_use
Apr 17 07:39:54.077061 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone object_type, name=use, global_conf=global_conf)
Apr 17 07:39:54.077383 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 406, in get_context
Apr 17 07:39:54.077675 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone global_conf=global_conf)
Apr 17 07:39:54.077980 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 296, in loadcontext
Apr 17 07:39:54.078274 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone global_conf=global_conf)
Apr 17 07:39:54.078576 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 328, in _loadegg
Apr 17 07:39:54.078869 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone return loader.get_context(object_type, name, global_conf)
Apr 17 07:39:54.079163 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 620, in get_context
Apr 17 07:39:54.079456 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone object_type, name=name)
Apr 17 07:39:54.079745 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 646, in find_egg_entry_point
Apr 17 07:39:54.080039 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone possible.append((entry.load(), protocol, entry.name))
Apr 17 07:39:54.080330 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 2324, in load
Apr 17 07:39:54.080619 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone return self.resolve()
Apr 17 07:39:54.080916 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone File "/usr/local/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 2330, in resolve
Apr 17 07:39:54.081241 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone module = __import__(self.module_name, fromlist=['__name__'], level=0)
Apr 17 07:39:54.081532 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone ImportError: No module named urlmap
Apr 17 07:39:54.081820 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: ERROR keystone
Apr 17 07:39:54.082114 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: unable to load app 0 (mountpoint='') (callable not found or import error)
Apr 17 07:39:54.082434 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: *** no app loaded. going in full dynamic mode ***
Apr 17 07:39:54.082723 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: --- no python application found, check your startup logs for errors ---
Apr 17 07:39:54.083015 ubuntu-xenial-rax-ord-0003552328 <email address hidden>[6403]: [pid: 6406|app: -1|req: -1/1] 23.253.160.56 () {50 vars in 792 bytes} [Tue Apr 17 07:39:54 2018] GET /identity/v3/ => generated 21 bytes in 0 msecs (HTTP/1.1 500) 3 headers in 102 bytes (0 switches on core 0)

[Dr. Jens Harbott (j-harbott)]

O.k., comparing with a similar but passing job (http://logs.openstack.org/86/547986/9/check/legacy-tempest-dsvm-neutron-scenario-multinode-lvm-multibackend/b299ddf/logs/dpkg-l.txt.gz) I found a difference:

ceph pkgs pull in python-paste pkg from upstream which seems to overwrite the pip-installed Paste. and even though it claims to be the same version (2.0.3), they seem to behave differently. On a node where it is broken, if I remove the python-paste pkg and install it from pip instead, keystone works again. Too bad that this implicitly uninstalls ceph ... :-(

So I think the trigger for this was moving UCA from pike to queens. Still would be good to come up with a forward going solution.

[Dr. Jens Harbott (j-harbott)]

This seems to be a packaging bug. The pip installation has a file

/usr/local/lib/python2.7/dist-packages/Paste-2.0.3-py2.7-nspkg.pth

while there is no similar file in the python-paste pkg. If I copy the above file to /usr/lib/python2.7/dist-packages/Paste-2.0.3-py2.7-nspkg.pth the error disappears.

[Dr. Jens Harbott (j-harbott)]

This is for version 2.0.3+dfsg-4ubuntu1~cloud0 of python-paste from Queens UCA.

[Dr. Jens Harbott (j-harbott)]

Ignore the previous statements, the issue did not reproduce itself on a fresh node. Seems devstack-plugin-ceph is the culprit by force-installing PasteDeploy:

2018-04-19 14:45:22.171 | ++ /opt/stack/new/devstack-plugin-ceph/devstack/plugin.sh:source:42 : pip_install -U --force PasteDeploy

I'll try to do a patch for the plugin.

[Dr. Jens Harbott (j-harbott)]

Hmm, seems that that hack was introduced when upgrading to UCA Pike: https://review.openstack.org/510660

So it seems just right to update if for Queens.