apparent deadlock on lock_bridge in n-cpu

[Doug Hellmann]

It's not clear if n-cpu is dying trying to acquire the lock "lock_bridge" or if it's just hanging.

http://logs.openstack.org/08/109108/1/check/check-tempest-dsvm-full/4417111/logs/screen-n-cpu.txt.gz

The logs for n-cpu stop about 15 minutes before the rest of the test run, and all tests doing things that require the hypervisor executed after that point fail with different errors.

[Joe Gordon (jogo)]

seeing this happening in the gate, but no good fingerprint for this in the logs.

https://gist.githubusercontent.com/cburgess/cde23a2129f75ac20000/raw/6538ccbebfa281484cccd81a267f0a27542f182f/gistfile1.txt

[Chet Burgess (cfb-n)]

As vishy pointed out it looks like iptables-save is never returning, or the locks are blocking greenthread from switching and thus returning the data and releasing the lock.

2014-08-18 16:21:25.183 DEBUG nova.openstack.common.lockutils [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] Got semaphore "4afac4bc-f7d8-470f-9c16-af270582e48e" internal_lock /opt/stack/new/nova/nova/openstack/common/lockutils.py:263
2014-08-18 16:21:25.183 DEBUG nova.openstack.common.lockutils [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] Got semaphore / lock "do_terminate_instance" inner /opt/stack/new/nova/nova/openstack/common/lockutils.py:324
2014-08-18 16:21:25.183 DEBUG nova.openstack.common.lockutils [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] Got semaphore "4afac4bc-f7d8-470f-9c16-af270582e48e-events" internal_lock /opt/stack/new/nova/nova/openstack/common/lockutils.py:263
2014-08-18 16:21:25.184 DEBUG nova.openstack.common.lockutils [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] Got semaphore / lock "_clear_events" inner /opt/stack/new/nova/nova/openstack/common/lockutils.py:324
2014-08-18 16:21:25.184 DEBUG nova.openstack.common.lockutils [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] Released semaphore "4afac4bc-f7d8-470f-9c16-af270582e48e-events" lock /opt/stack/new/nova/nova/openstack/common/lockutils.py:291
2014-08-18 16:21:25.184 DEBUG nova.openstack.common.lockutils [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] Semaphore / lock released "_clear_events" inner /opt/stack/new/nova/nova/openstack/common/lockutils.py:328
2014-08-18 16:21:25.277 AUDIT nova.compute.manager [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] [instance: 4afac4bc-f7d8-470f-9c16-af270582e48e] Terminating instance
2014-08-18 16:21:27.759 DEBUG nova.virt.libvirt.vif [req-fb34143f-be74-4719-a062-a9a041a46098 FloatingIPsTestXML-369233022 FloatingIPsTestXML-175936678] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=False,config_drive='',created_at=2014-08-18T16:21:07Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='floating_server-1914203176',display_name='floating_server-1914203176',ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,host='devstack-trusty-hpcloud-b1-1523392',hostname='floating-server-1914203176',id=22,image_ref='af86fee1-9d89-4003-bcfe-7bf1213c8d9a',info_cache=InstanceInfoCache,instance_type_id=6,kernel_id='ccbbcd46-394e-4875-b6eb-245467adf1e4',key_data=None,key_name=None,launch_index=0,launched_at=2014-08-18T16:21:16Z,launched_on='devstack-trusty-hpcloud-b1-1523392',locked=False,locked_by=None,memory_mb=64,metadata={},node='devstack-trusty-hpcloud-b1-1523392',os_type=None,pci_devices=<?>,power_state=1,progress=...

[Joe Gordon (jogo)]

It looks like iptables-save may be hanging

http://logs.openstack.org/77/109177/2/gate/gate-tempest-dsvm-full/97f2cde/logs/screen-n-cpu.txt.gz#_2014-08-18_16_21_27_763

[Joe Gordon (jogo)]

01:21 < cburgess> As far as I can tell we always use this threading.Semaphore. We should use to an eventlet
                  one back in the day but we don't anymore.
01:22 < cburgess> I think vishy might be onto something..
01:22 < cburgess> if debugger.enabled():
01:22 < cburgess> # turn off thread patching to enable the remote debugger
01:22 < cburgess> eventlet.monkey_patch(os=False, thread=False)
01:22 < cburgess> else:
01:22 < cburgess> eventlet.monkey_patch(os=False)
01:22 < cburgess> We don't pass thread=false unless the debugger is on.
01:23 < vishy> cburgess: right but the semaphore is way broke anyway
01:23 < vishy> so i think we are monkeypatching it but hitting the deadlock from the bug
01:24 < cburgess> Possibly...
01:26 < vishy> so it used to use eventlet.semaphore.Semaphore
01:27 < cburgess> Yup
01:27 < cburgess> Looks like it got changed a while back.
01:27 < cburgess> This change.
01:27 < cburgess> https://github.com/openstack/nova/commit/a0bcd7b90c38b104cb278223679cedf5cc11c74c
01:28 < vishy> it also added a specific lock
01:29 < vishy> around the threading semaphore
01:29 < vishy> not sure when tht was added
01:30 < cburgess> This one https://github.com/openstack/nova/commit/4b6ea1e1b87241918baf21a16817417226a9fc62

[Joe Gordon (jogo)]

Oslo patch https://review.openstack.org/#/c/43895/

[Joshua Harlow (harlowja)]

Isn't eventlet.monkey_patch(os=False, thread=False) wrought with madness?

It's so simple to deadlock when that is done.

Example @ https://gist.github.com/harlowja/9c35e443dfa136a4f965

[Chet Burgess (cfb-n)]

vishy postulated that it could be a by-product of this old bug (still not fixed in eventlet we believe).

https://bitbucket.org/eventlet/eventlet/issue/137/use-of-threading-locks-causes-deadlock

It looks like one or both of these changes is causing the issue.
https://github.com/openstack/nova/commit/a0bcd7b90c38b104cb278223679cedf5cc11c74c
https://github.com/openstack/nova/commit/4b6ea1e1b87241918baf21a16817417226a9fc62

Corresponding oslo reviews:
https://review.openstack.org/#/c/43895/
https://review.openstack.org/#/c/54581/

[Sean Dague (sdague)]

This really seems to be back on lock utils as the core issue, and Nova is just getting this behavior because lockutils is deadlocking.

[Ben Nemec (bnemec)]

Okay, so we're still thinking this is due to the mismatch of eventlet/threading locks in lockutils? I think we do have an issue there even when eventlet is monkey_patched fully:

>>> import threading
>>> threading.Lock
<built-in function allocate_lock>
>>> threading.Semaphore
<function Semaphore at 0x2355c08>
>>> import eventlet
>>> eventlet.monkey_patch()
>>> threading.Lock
<function allocate_lock at 0x25dd0c8>
>>> threading.Semaphore
<function Semaphore at 0x2355c08>

Apparently eventlet doesn't monkey_patch Semaphore, so we're using an eventlet Lock with a stdlib Semaphore.

So, to fix this without introducing an eventlet dep to lockutils we need to do the following:

1) Conditionally import eventlet
2) Any time we create a semaphore, check if we have eventlet and if it has monkeypatched thread, and explicitly use an eventlet semaphore if so.

Is my understanding of the current situation correct?

[Joshua Harlow (harlowja)]

Just fyi the sempahore object is based on a condition and lock:

http://hg.python.org/releasing/2.7.6/file/ba31940588b6/Lib/threading.py#l422

So if how all this monkey patches works is correct then self.__cond = Condition(Lock()) would be monkey patched by eventlet so that the Sempahore there would actually use a eventlet Lock(), maybe that's not how it turns out to work though?

[Joshua Harlow (harlowja)]

A little test of this:

>>> import eventlet
>>> eventlet.monkey_patch()
>>> import threading
>>> b = threading.Semaphore()
>>> b._Semaphore__cond
<Condition(<Semaphore c=1 _w[0]>, 0)>
>>> b._Semaphore__cond._Condition__lock
<Semaphore at 0x8704dcc c=1 _w[0]>
>>> a = b._Semaphore__cond._Condition__lock
>>> a.__module__
'eventlet.semaphore'
>>> b.__module__
'threading'
>>>

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/119586

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/119586
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=58d48ded2bbb90b8639a31b47e37e97c276eac87
Submitter: Jenkins
Branch: master

commit 58d48ded2bbb90b8639a31b47e37e97c276eac87
Author: Davanum Srinivas <email address hidden>
Date: Sat Sep 6 22:37:44 2014 -0400

    Sync oslo lockutils to nova

    The commit to be merged:

    942e1aa Use file locks by default again
    ac995be Fix E126 pep8 errors
    15b8352 Remove oslo.log from lockutils

    942e1aa is hopefully the fix for the "n-cpu stop about 15 minutes
    before the rest of the test run" problem at the gate. We need to
    make sure this actually fixes the gate problem

    Closes-Bug: #1349452

    Change-Id: I31265d4e08245879ad72d3e91dcd8be2359ca811