Nova UTs and functional tests broken due to cinderclient modifying i18n global vars

[Sylvain Bauza]

Python unittests and functional tests are trampled by our Translation system, and in particular the gettext module.

For example :
2016-05-30 05:45:25.217 | nova.tests.unit.virt.libvirt.test_driver.LibvirtConnTestCase.test_create_images_and_backing_images_exist
2016-05-30 05:45:25.218 | --------------------------------------------------------------------------------------------------------
2016-05-30 05:45:25.218 |
2016-05-30 05:45:25.218 | Captured traceback:
2016-05-30 05:45:25.218 | ~~~~~~~~~~~~~~~~~~~
2016-05-30 05:45:25.218 | Traceback (most recent call last):
2016-05-30 05:45:25.218 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
2016-05-30 05:45:25.218 | return func(*args, **keywargs)
2016-05-30 05:45:25.218 | File "nova/tests/unit/virt/libvirt/test_driver.py", line 8337, in test_create_images_and_backing_images_exist
2016-05-30 05:45:25.218 | conn = libvirt_driver.LibvirtDriver(fake.FakeVirtAPI(), False)
2016-05-30 05:45:25.218 | File "nova/virt/libvirt/driver.py", line 325, in __init__
2016-05-30 05:45:25.218 | host=self._host)
2016-05-30 05:45:25.219 | File "nova/virt/firewall.py", line 37, in load_driver
2016-05-30 05:45:25.219 | return fw_class(*args, **kwargs)
2016-05-30 05:45:25.219 | File "nova/virt/libvirt/firewall.py", line 335, in __init__
2016-05-30 05:45:25.219 | self.nwfilter = NWFilterFirewall(kwargs['host'])
2016-05-30 05:45:25.219 | File "nova/virt/libvirt/firewall.py", line 58, in __init__
2016-05-30 05:45:25.219 | LOG.warning(_LW("Libvirt module could not be loaded. "
2016-05-30 05:45:25.219 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/oslo_i18n/_factory.py", line 83, in f
2016-05-30 05:45:25.219 | return _message.Message(msg, domain=domain)
2016-05-30 05:45:25.219 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/oslo_i18n/_message.py", line 60, in __new__
2016-05-30 05:45:25.219 | msgtext = Message._translate_msgid(msgid, domain)
2016-05-30 05:45:25.219 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/oslo_i18n/_message.py", line 117, in _translate_msgid
2016-05-30 05:45:25.219 | fallback=True)
2016-05-30 05:45:25.220 | File "/usr/lib/python2.7/gettext.py", line 492, in translation
2016-05-30 05:45:25.220 | with open(mofile, 'rb') as fp:
2016-05-30 05:45:25.220 | IOError: [Errno 2] No such file or directory: '/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/share/locale/en_US.ISO8859-1/LC_MESSAGES/nova-log-warning.mo'
2016-05-30 05:45:25.220 |

Or :
2016-05-30 05:45:25.210 | nova.tests.unit.virt.libvirt.test_driver.LibvirtDriverTestCase.test_delete_instance_files_resize
2016-05-30 05:45:25.210 | ------------------------------------------------------------------------------------------------
2016-05-30 05:45:25.210 |
2016-05-30 05:45:25.210 | Captured pythonlogging:
2016-05-30 05:45:25.210 | ~~~~~~~~~~~~~~~~~~~~~~~
2016-05-30 05:45:25.210 | 2016-05-30 05:42:04,467 WARNING [nova.virt.libvirt.firewall] Libvirt module could not be loaded. NWFilterFirewall will not work correctly.
2016-05-30 05:45:25.210 | 2016-05-30 05:42:04,469 INFO [os_brick.initiator.connector] Init DISCO connector
2016-05-30 05:45:25.210 |
2016-05-30 05:45:25.210 |
2016-05-30 05:45:25.210 | Captured traceback:
2016-05-30 05:45:25.210 | ~~~~~~~~~~~~~~~~~~~
2016-05-30 05:45:25.211 | Traceback (most recent call last):
2016-05-30 05:45:25.211 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
2016-05-30 05:45:25.211 | return func(*args, **keywargs)
2016-05-30 05:45:25.211 | File "nova/tests/unit/virt/libvirt/test_driver.py", line 15409, in test_delete_instance_files_resize
2016-05-30 05:45:25.211 | result = self.drvr.delete_instance_files(instance)
2016-05-30 05:45:25.211 | File "nova/virt/libvirt/driver.py", line 7422, in delete_instance_files
2016-05-30 05:45:25.211 | LOG.info(_LI('Deleting instance files %s'), target_del,
2016-05-30 05:45:25.211 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/oslo_i18n/_factory.py", line 83, in f
2016-05-30 05:45:25.211 | return _message.Message(msg, domain=domain)
2016-05-30 05:45:25.211 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/oslo_i18n/_message.py", line 60, in __new__
2016-05-30 05:45:25.212 | msgtext = Message._translate_msgid(msgid, domain)
2016-05-30 05:45:25.212 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/oslo_i18n/_message.py", line 117, in _translate_msgid
2016-05-30 05:45:25.212 | fallback=True)
2016-05-30 05:45:25.212 | File "/usr/lib/python2.7/gettext.py", line 480, in translation
2016-05-30 05:45:25.212 | mofiles = find(domain, localedir, languages, all=1)
2016-05-30 05:45:25.212 | File "/usr/lib/python2.7/gettext.py", line 463, in find
2016-05-30 05:45:25.212 | if os.path.exists(mofile_lp):
2016-05-30 05:45:25.212 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1062, in __call__
2016-05-30 05:45:25.212 | return _mock_self._mock_call(*args, **kwargs)
2016-05-30 05:45:25.212 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1121, in _mock_call
2016-05-30 05:45:25.212 | result = next(effect)
2016-05-30 05:45:25.213 | File "/home/jenkins/workspace/gate-nova-python27-db/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 109, in next
2016-05-30 05:45:25.213 | return _next(obj)
2016-05-30 05:45:25.213 | StopIteration

Occurrences seem to start on May 27th after 00:00UTC :
http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22%2C%20line%20463%2C%20in%20find%5C%22%20AND%20project%3A%5C%22openstack%2Fnova%5C%22&from=7d
http://logstash.openstack.org/#/dashboard/file/logstash.json?query=message:\%22nova-log-warning.mo\%22%20AND%20project:\%22openstack%2Fnova\%22&from=7d

[Markus Zoeller (markus_z) (mzoeller)]

It's possible that this commit caused this: https://github.com/openstack/nova/commit/ece7b8f

[Sylvain Bauza (sylvain-bauza)]

Locally reverting https://github.com/openstack/nova/commit/ece7b8f didn't make the job passing :(

Still can't find why a stored venv still works while a new venv is having this problem, while the requirements versions are identical...

[Markus Zoeller (markus_z) (mzoeller)]

A wild guess: "Sphinx" released version 1.4.2 [1] yesterday. It uses "babel" [2], which is used for translating the "*.pot" files to "*.mo" files. Logstash query [3] suggests this time frame.
As said, this is just a wild guess.

References:
[1] https://pypi.python.org/pypi/Sphinx
[2] https://pypi.python.org/pypi/Babel/
[3] http://logstash.openstack.org/#dashboard/file/logstash.json?query=build_name%3A%5C%22gate-nova-python27-db%5C%22%20AND%20message%3A%5C%22with%20open(mofile%2C%20'rb')%20as%20fp%3A%5C%22%20AND%20NOT%20build_change%3A303345

[Sven Anderson (ansiwen)]

Why is the language set to en_US.ISO8859-1? There are no english language files, so gettext shouldn't look for them. Maybe the ISO8859-1 irritates the system and it treats it as a non-english language that needs to be translated?

[Michal Pryc (mpryc)]

I'm pretty sure it's caused by the improper pip module being installed.

Here is the diff between version which I'm 100% sure was running properly and current tests.

Seems like fixtures 3.0.0 is installed even if specified <2.0.
Another difference is os-testr which is now 0.7.0 and was 0.6.0.

Even pinning those version in the test-requirements.txt causes higher versions to be installed, meaning change was somewhere in other deps.

< fixtures==3.0.0
---
> fixtures==1.4.0
83c84
< os-testr==0.7.0
---
> os-testr==0.6.0
105c106
< python-cinderclient==1.7.1
---
> python-cinderclient==1.6.0
114c115
< python-openstackclient==2.5.0
---
> python-openstackclient==2.4.0

[Michal Pryc (mpryc)]

Installing older version of cinderclient fixes the issue.

Wondering if this is relevant:
https://bugs.launchpad.net/cinder/+bug/1277005

[Michal Pryc (mpryc)]

This change broke it:
https://github.com/openstack/requirements/commit/c682e3b8355b3e4648e3ec6158f6b4a2758be71a#diff-0bdd949ed8a7fdd4f95240bd951779c8

[Sylvain Bauza (sylvain-bauza)]

Confirming with Migi is saying, downgrading cinderclient to 1.6.0 fixes the problem (and upgrading back to 1.7.1 raises the issue again) :
http://paste.openstack.org/show/506299/

That's the weirdest thing ever. Still investigating why that foolish thing is not working.

[Sylvain Bauza (sylvain-bauza)]

Okay, I think I found the root case.

https://review.openstack.org/#/c/294751/ was introduced on 2016-04-12 but only tagged for 1.7.0 on http://git.openstack.org/cgit/openstack/python-cinderclient/commit/?id=0cdcfb5988f57da80551b1a11fcd3d96d0baf1d8 (which was reverted quickly) and then only applied again when 1.7.1 was pushed to upper-constraints.txt ( https://github.com/openstack/requirements/commit/c682e3b8355b3e4648e3ec6158f6b4a2758be71a#diff-0bdd949ed8a7fdd4f95240bd951779c8 )

It seems the new cinderclient globally modifies the translation catalog lookup fonctions (LW, LI, etc.) *globally* : https://review.openstack.org/#/c/294751/2/cinderclient/_i18n.py

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/322878

[Victor Stinner (vstinner)]

It looks like a duplicate of my cinderclient bug report: https://bugs.launchpad.net/python-cinderclient/+bug/1587071

[Sylvain Bauza (sylvain-bauza)]

https://review.openstack.org/322899 is planned to temporarly resolve the problem by blocking cinderclient-1.7.1 until https://review.openstack.org/322878 is merged and shipped to Nova.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/322878
Committed: https://git.openstack.org/cgit/openstack/python-cinderclient/commit/?id=623cef2d5c5d9f375c60c991f5ab9f951e9253fa
Submitter: Jenkins
Branch: master

commit 623cef2d5c5d9f375c60c991f5ab9f951e9253fa
Author: Victor Stinner <email address hidden>
Date: Mon May 30 17:06:31 2016 +0200

    Don't enable lazy translation when loading client

    The change I9c8db9487b554b637a41620c858a7e7abf802879 introduced a
    regression in nova and trove. Importing cinderclient.client now calls
    _i18n.enable_lazy() which calls oslo_i18n.enable_lazy(). It's wrong to
    modify a global variable (oslo_i18n._lazy.USE_LAZY) when a module is
    imported.

    This change removes the call to _i18n.enable_lazy() from client.py.

    Closes-Bug: #1587071
    Related-Bug: 1586976
    Change-Id: I1512b86815e7248fa226c6969124ddc654145562

[Markus Zoeller (markus_z) (mzoeller)]

Commit [1] solved bug 1587071. Bug 1586976 is a duplicate to bug 1587071.

References:
[1] https://git.openstack.org/cgit/openstack/python-cinderclient/commit/?id=623cef2d5c5d9f375c60c991f5ab9f951e9253fa

[Sylvain Bauza (sylvain-bauza)]

Well, Nova was fixed by https://review.openstack.org/#/c/322899/ rather than https://git.openstack.org/cgit/openstack/python-cinderclient/commit/?id=623cef2d5c5d9f375c60c991f5ab9f951e9253fa (because it would mean that we should wait for a new cinderclient version) but okay.