Race in resource tracker causes 500 response on deleting during verify_resize state

Yeah I was just looking at this coincidentally.

message:"get_volume_size" AND message:"No such device or address" AND tags:"screen-n-cpu.txt"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiZ2V0X3ZvbHVtZV9zaXplXCIgQU5EIG1lc3NhZ2U6XCJObyBzdWNoIGRldmljZSBvciBhZGRyZXNzXCIgQU5EIHRhZ3M6XCJzY3JlZW4tbi1jcHUudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MTExNDM3NDY0MjIsIm1vZGUiOiIiLCJhbmFseXplX2ZpZWxkIjoiIn0=

That shows up in 88% success runs too though.

This is better:

message:"_confirm_resize_on_deleting" AND message:"MessagingTimeout" AND tags:"screen-n-api.txt"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiX2NvbmZpcm1fcmVzaXplX29uX2RlbGV0aW5nXCIgQU5EIG1lc3NhZ2U6XCJNZXNzYWdpbmdUaW1lb3V0XCIgQU5EIHRhZ3M6XCJzY3JlZW4tbi1hcGkudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MTExNTAxNTU5MzAsIm1vZGUiOiIiLCJhbmFseXplX2ZpZWxkIjoiIn0=

32 hits in 7 days, check and gate, all failures.

e-r query: https://review.openstack.org/#/c/122811/

Looking for recent suspect changes:

https://github.com/openstack/nova/commit/baabab45e0ae0e9e35872cae77eb04bdb5ee0545

https://github.com/openstack/nova/commit/4c4dc3a6d331426e472e2dd1e9b0513da7cb7450

From the same job run as above, the volume is deleted here:

http://logs.openstack.org/10/110110/40/check/check-tempest-dsvm-postgres-full/4cd8a81/logs/screen-c-vol.txt.gz#_2014-09-19_10_24_31_914

So the volume is deleted within milliseconds of when the update_available_resource periodic task runs. We run that task every minute. We hit the failure and dump a stack trace in the logs.

As a partial bug fix we could catch the ProcessExecutionError and check the stderr for "No such device or address" and just log that as an info message. That would reduce the thousands of traces in the normal gate runs for an expected teardown issue.

Some investigation in IRC:

(2:26:59 PM) mriedem: here is when update_available_resource starts:
(2:26:59 PM) mriedem: 2014-09-19 10:23:00.539 21095 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /opt/stack/new/nova/nova/openstack/common/periodic_task.py:193
(2:27:05 PM) mriedem: 2014-09-19 10:23:00.540 21095 DEBUG nova.openstack.common.lockutils [-] Acquired semaphore "compute_resources" lock /opt/stack/new/nova/nova/openstack/common/lockutils.py:229
(2:27:05 PM) alaski: I'm looking about three lines up
(2:27:26 PM) mriedem: then we fail and release that lock
(2:27:26 PM) alaski: 2014-09-19 10:23:07.991 DEBUG nova.openstack.common.lockutils [req-5a467708-5da4-446b-b729-c44d005f84c3 DeleteServersTestJSON-14297441 DeleteServersTestJSON-1574463718] Using existing semaphore "compute_resources" internal_lock /opt/stack/new/nova/nova/openstack/common/lockutils.py:202
(2:27:26 PM) mriedem: 2014-09-19 10:24:31.404 21095 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /opt/stack/new/nova/nova/openstack/common/lockutils.py:275
(2:27:56 PM) mriedem: 10:23:00 to 10:24:31
(2:27:56 PM) alaski: 2014-09-19 10:24:31.623 DEBUG nova.openstack.common.lockutils [req-5a467708-5da4-446b-b729-c44d005f84c3 DeleteServersTestJSON-14297441 DeleteServersTestJSON-1574463718] Acquired semaphore "compute_resources" lock /opt/stack/new/nova/nova/openstack/common/lockutils.py:229
(2:27:56 PM) alaski: req-5a467708-5da4-446b-b729-c44d005f84c3 is what's timing out
(2:28:07 PM) mriedem: yeah so that's your 90 seconds
(2:28:13 PM) mriedem: where we have a 60 second messaging timeout in between
(2:29:16 PM) alaski: yep
(2:30:40 PM) alaski: it seems that update_available_resources needs to be reworked so that it doesn't hold the lock too long
(2:30:49 PM) mriedem: yeah

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

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

Moving up to critical, as this is bouncing us quite a bit in the gate now

Reviewed: https://review.openstack.org/122873
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=9a570111d953f7b2a5bd2b4f47dda353f2aba78c
Submitter: Jenkins
Branch: master

commit 9a570111d953f7b2a5bd2b4f47dda353f2aba78c
Author: Matt Riedemann <email address hidden>
Date: Fri Sep 19 12:49:31 2014 -0700

    Handle volume bdm not found in lvm.get_volume_size

    We're stack tracing in successful gate runs because of a race when
    deleting an instance and when the update_available_resource periodic
    task is running.

    When we hit the race, the volume that's backing the instance is deleted
    and the periodic task (virt driver) is trying to get the current
    information about the volume, which no longer exists and we fail and
    short-circuit the update_available_resource task.

    This change adds a decorator which checks if a ProcessExecutionError is
    due to the device no longer existing and if so, raises
    VolumeBDMPathNotFound, and applies that decorator to the get_volume_size
    method.

    Related-Bug: #1371677

    Change-Id: Ic452df82c61087efda8d742e030076421c0c813b

Reviewed: https://review.openstack.org/122874
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=76bc4ac549b2c8b70b67458717e793defb048d2c
Submitter: Jenkins
Branch: master

commit 76bc4ac549b2c8b70b67458717e793defb048d2c
Author: Matt Riedemann <email address hidden>
Date: Fri Sep 19 13:47:42 2014 -0700

    Handle VolumeBDMPathNotFound in _get_disk_over_committed_size_total

    This handles the VolumeBDMPathNotFound error bubbling up from
    _get_instance_disk_info during the update_available_resource periodic
    task.

    Related-Bug: #1371677

    Change-Id: I10c20f3f5f96003fe69fcdc9133c661e6dc009b4

I added some time testing for the update_available_resources periodic task:

http://logs.openstack.org/38/123438/1/check/check-tempest-dsvm-neutron-full/95c1ef2/logs/screen-n-cpu.txt.gz?

Just filter on error, can see that sometimes it takes a very long time to run:

2014-09-23 16:51:51.494 32200 ERROR nova.compute.manager [-] update_available_resource took 0.296182155609 secs
2014-09-23 16:52:40.761 32200 ERROR nova.compute.manager [-] update_available_resource took 0.17028093338 secs
2014-09-23 16:53:40.887 32200 ERROR nova.compute.manager [-] update_available_resource took 0.109967947006 secs
2014-09-23 16:54:41.639 32200 ERROR nova.compute.manager [-] update_available_resource took 0.105166912079 secs
2014-09-23 16:55:43.663 32200 ERROR nova.compute.manager [-] update_available_resource took 0.128235816956 secs
2014-09-23 16:56:45.131 32200 ERROR nova.compute.manager [-] update_available_resource took 1.59690380096 secs
2014-09-23 16:57:46.012 32200 ERROR nova.compute.manager [-] update_available_resource took 1.47475099564 secs
2014-09-23 16:58:46.088 32200 ERROR nova.compute.manager [-] update_available_resource took 1.55297207832 secs
2014-09-23 16:59:47.132 32200 ERROR nova.compute.manager [-] update_available_resource took 2.59809398651 secs
2014-09-23 17:00:46.144 32200 ERROR nova.compute.manager [-] update_available_resource took 0.605221986771 secs
2014-09-23 17:00:52.047 32200 ERROR nova.compute.manager [-] [instance: 56a02698-d951-436c-82f4-c0ec4dafa199] An error occurred while refreshing the network cache.
2014-09-23 17:01:47.637 32200 ERROR nova.compute.manager [-] update_available_resource took 1.10360908508 secs
2014-09-23 17:02:50.673 32200 ERROR nova.compute.manager [-] update_available_resource took 2.13903999329 secs
2014-09-23 17:03:50.816 32200 ERROR nova.compute.manager [-] update_available_resource took 1.28159403801 secs
2014-09-23 17:04:51.604 32200 ERROR nova.compute.manager [-] update_available_resource took 1.06992197037 secs
2014-09-23 17:05:51.215 32200 ERROR nova.compute.manager [-] update_available_resource took 0.680285930634 secs
2014-09-23 17:08:04.722 32200 ERROR nova.compute.manager [-] update_available_resource took 73.1881198883 secs
2014-09-23 17:08:08.014 32200 ERROR nova.compute.manager [-] update_available_resource took 0.926635026932 secs
2014-09-23 17:08:54.234 32200 ERROR nova.compute.manager [-] update_available_resource took 0.698902130127 secs
2014-09-23 17:09:54.044 32200 ERROR nova.compute.manager [-] update_available_resource took 0.510345935822 secs
2014-09-23 17:10:56.615 32200 ERROR nova.compute.manager [-] update_available_resource took 1.00940585136 secs
2014-09-23 17:11:56.171 32200 ERROR nova.compute.manager [-] update_available_resource took 0.573462963104 secs
2014-09-23 17:12:59.232 32200 ERROR nova.compute.manager [-] update_available_resource took 1.69808387756 secs
2014-09-23 17:13:59.958 32200 ERROR nova.compute.manager [-] update_available_resource took 0.424647808075 secs
2014-09-23 17:15:01.642 32200 ERROR nova.compute.manager [-] update_available_resource took 1.10785794258 secs
2014-09-23 17:16:03.711 32200 ERROR nova.compute.manager [-] update_available_resource took 0...

Looks like when the periodic task is slow all the time is consumed in _get_disk_over_committed_size_total

http://logs.openstack.org/38/123438/2/check/check-tempest-dsvm-neutron-full/bb1dbb6/logs/screen-n-cpu.txt.gz?#_2014-09-24_03_09_56_913

yeh, this seems to be command timing out:

2014-09-24 03:07:59.449 32123 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf blockdev --getsize64 /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2010-10.org.openstack:volume-16ab2d39-59d6-4110-88fa-ab60332adf19-lun-1 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:161
2014-09-24 03:09:56.856 32123 DEBUG nova.openstack.common.processutils [-] Result was 1 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:195

grep processutils screen-n-cpu.txt.gz | grep 32123

To get only the periodic job executions

From IRC, danpb pointed out that blockdev is blocking on purpose, and when the volume is gone that will take awhile, so that's what's causing the lock to be held so long:

http://logs.openstack.org/38/123438/2/check/check-tempest-dsvm-neutron-full/bb1dbb6/logs/screen-n-cpu.txt.gz?#_2014-09-24_03_09_56_913

2014-09-24 03:09:56.913 32123 ERROR nova.virt.libvirt.driver [-] _get_disk_over_committed_size_total took 117.755759954 secs

That's taking nearly 2 minutes.

From danpb:

(10:48:04 AM) danpb: sdague: blockdev taking a long time is a sign that the underlying storage is dead
(10:48:20 AM) danpb: eg, could be an iSCSI lun for which the iscsi server is no longer running
(10:48:20 AM) dansmith: and this is blockdev on an iscsi target, right?
(10:48:36 AM) sdague: yep
danieru danpb dansmith
(10:48:56 AM) sdague: so is there a non blocking way to poke that?
(10:48:56 AM) danpb: so good to check to see that cinder still has the corresponding iscsi server active when this happens
(10:49:00 AM) mriedem: danpb: is there a quicker way to find out up front if the bdm is gone?
(10:49:17 AM) sdague: because the issue is this goes off into a blocking call for 2 minutes
(10:49:17 AM) danpb: not that i know of, off hand
(10:49:21 AM) sdague: which is holding locks
(10:49:27 AM) danpb: generally this turns into an uninterruptable sleep in the kernel
(10:49:31 AM) sdague: and .... other stuff times out
(10:49:42 AM) dansmith: yeah, it's blocking by design
(10:49:50 AM) sdague: dansmith: yep
(10:49:52 AM) mriedem: ok, could we call off to cinder to find out of the volume is deleted?
(10:49:53 AM) dansmith: because you can't really tell that it's gone until it times out
(10:49:56 AM) mriedem: *if
(10:49:57 AM) danpb: being non-blocking on I/O errors is a good way to get data corruption
(10:50:08 AM) danpb: so the kernel generally avoids that

So we need a patch that checks if the volume is gone (non-blocking) before we call blockdev to get the size of the volume, that should free us up here. When I looked at this on Friday, the cinder logs were showing that the volume was deleted right around the time that we had the blockdev failure and stacktrace, so we can probably go back to cinder and see if the volume has been deleted just by it's state and then short circuit our work in _get_instance_disk_info.

Pulling this together, the update_available_resource periodic task is using the resource tracker to update host stats, and that rt method is locking on the 'compute_resource' lock, which is also what the resize_claim and drop_resize_claim methods in the resource tracker are locked on, and that's where we hit the timeout in the resize test - it's waiting to make a resize claim but the blockdev blocking call in the update_available_resource periodic task is taking too long, causing the 60 second RPC messaging timeout for the resize claim in the test run.

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

Reviewed: https://review.openstack.org/123774
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=84ff466c8338cc44ca92a0f1673e204dd720c7d9
Submitter: Jenkins
Branch: master

commit 84ff466c8338cc44ca92a0f1673e204dd720c7d9
Author: Dan Smith <email address hidden>
Date: Wed Sep 24 09:05:26 2014 -0700

    Reduce the scope of RT work while holding the big lock

    This makes the RT.update_available_resource() method do what it
    can in the way of prep work before grabbing the lock to update
    the database stats.

    Change-Id: I1132e2ab99427688529566c1a1fffb33eab07f3f
    Related-Bug: #1371677

Since https://review.openstack.org/#/c/123774/ merged there is a significant drop off in the race, so looks like that stemmed the bleeding. This is probably not a critical rc1 issue now. We should still put something in the libvirt driver to check if the volume bdm exists before calling the blocking blockdev command to get the volume size, but that could be a follow on improvement.

We've landed a related fix to this. It's going to take 24hrs to figure out if this is under control. If not, will reopen.

I think this is still an rc1 bug, it's something we've been focussing a ton of time on of late.

I've looking at the following logfile

http://logs.openstack.org/23/119523/9/check/check-tempest-dsvm-neutron-full/41505f7/logs/screen-n-cpu.txt.gz?level=TRACE#_2014-09-22_19_34_39_385

We can see a hot-unplug operation start for a cinder volume 6f88ab3e-9edd-4fbf-857e-2d6d87f98e39 at 19:32:32

2014-09-22 19:32:32.963 AUDIT nova.compute.manager [req-840df9bc-aee9-48d9-baa3-d58392954b0d ServerRescueNegativeTestJSON-161189933 ServerRescueNegativeTestJSON-667937194] [instance: 7b20e76a-48a0-4dd4-b2b6-bb3b1056b711] Detach volume 6f88ab3e-9edd-4fbf-857e-2d6d87f98e39 from mountpoint /dev/vdb

At 19:32:52 the periodic task starts to update resources

2014-09-22 19:32:52.747 31561 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /opt/stack/new/nova/nova/openstack/common/periodic_task.py:193

The libvirt get_available_resource method calls _get_instance_disk_info on each running VM.

This method queries the libvirt guest XML to get a list of disks present on the VM. It queries the database to get a list of attached cinder volumes. It then filters the list of disks from the XML removing the list of cinder volumes

None the less at 19:32:53 we see the code try to run blockdev on iSCSI LUN with serial number 6f88ab3e-9edd-4fbf-857e-2d6d87f98e39:

2014-09-22 19:32:53.025 31561 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf blockdev --getsize64 /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2010-10.org.openstack:volume-6f88ab3e-9edd-4fbf-857e-2d6d87f98e39-lun-1 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:161

this path is the Cinder volume we just started to hotunplug at 19:32:32 (eg 20 seconds earlier).

What this says is that from Nova's POV the block device is no longer attached, but from libvirt's XML point the block device is still attached.

At 19:34:39 the blockdev command times out

2014-09-22 19:34:39.385 31561 ERROR nova.openstack.common.periodic_task [-] Error during ComputeManager.update_available_resource: Unexpected error while running command.
Command: sudo nova-rootwrap /etc/nova/rootwrap.conf blockdev --getsize64 /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2010-10.org.openstack:volume-6f88ab3e-9edd-4fbf-857e-2d6d87f98e39-lun-1
Exit code: 1
Stdout: u''
Stderr: u'blockdev: cannot open /dev/disk/by-path/ip-127.0.0.1:3260-iscsi-iqn.2010-10.org.openstack:volume-6f88ab3e-9edd-4fbf-857e-2d6d87f98e39-lun-1: No such device or address\n'

This indicates that the iscsi volume has now been removed, presumably because the earlier cinder detach operation has succeeded.

It is conceivable that if the 'blockdev' command tries to access the iSCSI lun at precisely the wrong moment it might hang as the iSCSI connection is torn down, rather than getting the 'No such device or address' error.

So to me the root cause problem here is the _get_instance_disk_info method. The way it is written to query the libvirt XML and filter from known cinder volumes is clearly racy. If we can re-write the method to avoid that race, then we'd in turn avoid runing blockdev command on cinder volumes & thus av...

The race appears fixed with Dan Smith's locking change, since logstash results are back this hasn't shown up since his change merged.

I doubt that Dan's locking change fixed it, probably just made it less likely to occur. From code inspection alone I can see the potential for race is there in libvirt driver code.

One more thing:

looking at the orriginal patch (http://logs.openstack.org/10/110110/40/check/check-tempest-dsvm-postgres-full/4cd8a81/logs/screen-n-cpu.txt.gz#_2014-09-19_10_24_31_404) and matts fix here https://review.openstack.org/122874 - we should never be hitting that exception in the gate because: this exception should never happen in _get_instance_disk_info UNLESS we are running LVM backed instances - which afaiu never happens in the gate.

So there seems to be another bug here which we should report.

Don't be misled by the fact that "get_volume_size" is in the lvm.py module. This method is actually called for *any* block device, not only LVM. So the call is explained by the race wrt cinder iSCSI volumes I mentioned in comment #23. LVM is a red herring

As Dan nicely points out in comment #23 - this is due to the race described. The real bug is using the libvirt XML to find out about local discs (or anything for that matter) and especially not mix Nova db information. I will report a bug for this.

Related fix https://review.openstack.org/#/c/174836/.

Reviewed: https://review.openstack.org/174836
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=833357301bc80a27422f7bf081fae2d3da730a24
Submitter: Jenkins
Branch: master

commit 833357301bc80a27422f7bf081fae2d3da730a24
Author: Nikola Dipanov <email address hidden>
Date: Fri Apr 17 12:49:13 2015 +0100

    libvirt: make _get_instance_disk_info conservative

    We want to make sure we never try to get the size of an attached volume
    when doing _get_instance_disk_info (as this can cause issues when
    gathering available resources).

    libvirt's get_available_resources will call upon it to determine the
    available disk size on the compute node, but do so without providing
    information about block devices. This makes _get_instance_disk_info make
    incorrect guesses as to which device is a volume

    This patch makes the _get_instance_disk_info be more conservative about
    it's guesses when it can not reasonably determine if a device is a
    volume or not.

    Change-Id: Ifb20655c32896b640672917e3840add81b136780
    Partial-bug: #1445021
    Partial-Bug: #1371677

Fix proposed to branch: stable/kilo
Review: https://review.openstack.org/179500

Change abandoned by Jay Bryant (<email address hidden>) on branch: stable/kilo
Review: https://review.openstack.org/179500
Reason: No one has been begging for this. Abandoning.