keystone fails with: ArgsAlreadyParsedError: arguments already parsed: cannot register CLI option

[Ihar Hrachyshka]

Grenade jobs in master fail with the following scenario:

- grenade.sh attempts to list glance images [1];
- glance fails because keystone httpd returns 500 [2];
- keystone fails because "ArgsAlreadyParsedError: arguments already parsed: cannot register CLI option" [3]

Sean Dague says that it's because grenade does not upgrade keystone script, and the script should not even be installed in a way it's now installed (copied into /var/www/...).

Relevant thread: http://lists.openstack.org/pipermail/openstack-dev/2015-June/067147.html

[1]: http://logs.openstack.org/66/185066/3/check/check-grenade-dsvm-neutron/45d8663/logs/grenade.sh.txt.gz#_2015-06-18_09_08_32_989
[2]: http://logs.openstack.org/66/185066/3/check/check-grenade-dsvm-neutron/45d8663/logs/new/screen-g-api.txt.gz#_2015-06-18_09_08_42_531
[3]: http://logs.openstack.org/66/185066/3/check/check-grenade-dsvm-neutron/45d8663/logs/apache/keystone.txt.gz#_2015-06-18_09_08_46_675874

[Brant Knudson (blk-u)]

Check out this error: http://logs.openstack.org/66/185066/3/check/check-grenade-dsvm-neutron/45d8663/logs/apache/keystone.txt.gz#_2015-06-18_09_08_31_715671

mod_wsgi (pid=17229): Target WSGI script '/var/www/keystone/admin' cannot be loaded as Python module.
mod_wsgi (pid=17229): Exception occurred processing WSGI script '/var/www/keystone/admin'.
...
ImportError: cannot import name excutils

How could that possibly happen?

[Brant Knudson (blk-u)]

Current thinking is that during the upgrade process, different bits that keystone is using are getting upgraded from underneath the process.

When you run keystone in eventlet it's going to load the modules on startup and it doesn't get potentially restarted on each request.

Whereas when you run in mod_wsgi it loads when the request come in and again on any request. So if modules are getting upgraded while it's processing requests you can expect failures.

Not sure what the fix is. Running keystone in a virtualenv would probably do it.

[Brant Knudson (blk-u)]

Also, what looks like it's happening is that wsgi

1) wsgi tries starting a keystone worker
2) keystone does some things that affect process-global state, like registering config options, loading drivers
3) while this is going on, something else is mucking with installed python modules, causing keystone to raise exception
4) exception bubbles up and wsgi says it failed to start
5) wsgi tries starting keystone again in the same worker...
6) so keystone tries doing the same things again that affect process-global state, but keystone assumes starting with clean state,
     so it will just keep failing to start in this process.

So maybe keystone is doing something wrong here in that it can't clean up after itself, but the whole process is flawed and things are always going to be failing if the libraries are being changed from underneath the process.

[Brant Knudson (blk-u)]

Based on this I'm going to say there isn't a bug in keystone that can be fixed.

[Dolph Mathews (dolph)]

This smells like a circular dependency, but I could not identify one.

[Sean Dague (sdague)]

So, this still doesn't feel like it explains why this is failing at about a 25% rate on the neutron job, but not at all on the nova-net jobs.

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiQXJnc0FscmVhZHlQYXJzZWRFcnJvcjogYXJndW1lbnRzIGFscmVhZHkgcGFyc2VkOiBjYW5ub3QgcmVnaXN0ZXIgQ0xJIG9wdGlvblwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDM1MjQ2ODM0NDUxLCJtb2RlIjoic2NvcmUiLCJhbmFseXplX2ZpZWxkIjoiYnVpbGRfbmFtZSJ9

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ihar Hrachyshka (<email address hidden>) on branch: master
Review: https://review.openstack.org/195437
Reason: The latest failure logs suggest that it does not fix an issue. Even more interesting is that keystone import is failing, so library updates are probably not related.

[Ihar Hrachyshka (ihar-hrachyshka)]

Added neutron since it hits neutron jobs only.

One theory behind why it's neutron only is that if neutron is installed, we can see that pip does some downgrade/upgrade dance at least for one oslo library when installing neutron and neutron-*aas: oslo.middleware is downgraded to 1.x, then upgraded to 2.x.

[Ihar Hrachyshka (ihar-hrachyshka)]

Another case of failure is keystone failing on import from keystone.* namespace: http://logs.openstack.org/77/195277/16/check/check-grenade-dsvm-neutron/99916dc/logs/apache/keystone.txt.gz

2015-06-26 11:22:06.802800 mod_wsgi (pid=31793): Target WSGI script '/var/www/keystone/admin' cannot be loaded as Python module.
2015-06-26 11:22:06.802814 mod_wsgi (pid=31793): Exception occurred processing WSGI script '/var/www/keystone/admin'.
2015-06-26 11:22:06.802831 Traceback (most recent call last):
2015-06-26 11:22:06.802858 File "/var/www/keystone/admin", line 17, in <module>
2015-06-26 11:22:06.802884 from keystone.server import wsgi as wsgi_server
2015-06-26 11:22:06.802891 File "/opt/stack/new/keystone/keystone/server/wsgi.py", line 30, in <module>
2015-06-26 11:22:06.802911 from keystone.server import common
2015-06-26 11:22:06.802918 File "/opt/stack/new/keystone/keystone/server/common.py", line 17, in <module>
2015-06-26 11:22:06.802929 from keystone import backends
2015-06-26 11:22:06.802935 File "/opt/stack/new/keystone/keystone/backends.py", line 13, in <module>
2015-06-26 11:22:06.802946 from keystone import assignment
2015-06-26 11:22:06.802952 File "/opt/stack/new/keystone/keystone/assignment/__init__.py", line 15, in <module>
2015-06-26 11:22:06.802962 from keystone.assignment import controllers # noqa
2015-06-26 11:22:06.802969 File "/opt/stack/new/keystone/keystone/assignment/controllers.py", line 26, in <module>
2015-06-26 11:22:06.802980 from keystone.assignment import schema
2015-06-26 11:22:06.803004 ImportError: cannot import name schema

[Brant Knudson (blk-u)]

One thing in that the logs show is that some packages wind up being downgraded... e.g., when keystone is installed you get

2015-06-18 09:05:32.117 | Collecting oslo.middleware!=2.0.0,>=1.2.0 (from keystone==2015.2.0.dev1)
2015-06-18 09:05:32.145 | Downloading http://pypi.IAD.openstack.org/packages/py2.py3/o/oslo.middleware/oslo.middleware-2.1.0-py2.py3-none-any.whl

but then in glance install it's

2015-06-18 09:06:19.249 | Collecting oslo.middleware<1.1.0,>=1.0.0 (from oslo.messaging>=1.8.0->glance==2015.2.0.dev91)
2015-06-18 09:06:19.276 | Downloading http://pypi.IAD.openstack.org/packages/py2.py3/o/oslo.middleware/oslo.middleware-1.0.0-py2.py3-none-any.whl

So now oslo.middleware is downgraded to where keystone supposedly doesn't support it.

[simon yang (yang-chenjun)]

It hits me when I try to create service for keystone.

# openstack service create --name keystone --os-token xxxxxxxxxxxx --os-url http://xxxxxxx:35357/v2.0 --description "OpenStack Identity Service" identity

# ArgsAlreadyParseError: arguments already parsed: cannot register CLI option

[Yu Yin (35686556-h)]

same error which simon yang (yang-chenjun) wrote above:

# openstack service create --name keystone --os-token xxxxxxxxxxxx --os-url http://xxxxxxx:35357/v2.0 --description "OpenStack Identity Service" identity

# ArgsAlreadyParseError: arguments already parsed: cannot register CLI option

[Yu Yin (35686556-h)]

Use the lastest keystone from github.com/openstack/keystone fix my issue.

Thank you.

[Ihar Hrachyshka (ihar-hrachyshka)]

Haven't seen the failure for a long time. Some bug fairy apparently fixed it while I was sleeping.

[Kindjal (kindjal)]

For whatever it's worth, I'm seeing this now with stable/kilo in a fresh install on Ubuntu Trusty installing with pyenv + virtualenv with python 2.7.10.

[Dolph Mathews (dolph)]

I suspect this is easily reproducible if you run keystone stable/kilo under an external WSGI server (Apache httpd) using stable/juno's example WSGI script:

  stable/juno: https://github.com/openstack/keystone/blob/stable/juno/httpd/keystone.py

  stable/kilo: https://github.com/openstack/keystone/blob/stable/juno/httpd/keystone.py

I'm sure we'll see similar issues between stable/kilo and stable/liberty, as well.

[Launchpad Janitor (janitor)]

[Expired for OpenStack Identity (keystone) because there has been no activity for 60 days.]

[Sean Dague (sdague)]

This grenade bug was last updated over 180 days ago, as grenade
is a fast moving project and we'd like to get the tracker down to
currently actionable bugs, this is getting marked as Invalid. If the
issue still exists, please feel free to reopen it.

[Xiang Zhang (xiangz)]

I encounter a similar problem in our upgrade process. The root cause for us is that keystone is upgraded parallel with neutron, both rely on python-routes(in our environment). keystone starts while neutron uninstalls python-routes. One thing to note is that the log may not reveal the real module missing due to a bug in Python2 import mechnism: https://bugs.python.org/issue32479.