CapacityFilter intermittently fails in the gate due to insufficient virtual space on the host

More recent occurrence of the issue: http://logs.openstack.org/64/519664/3/check/tempest-full/dbb3f0e/controller/logs/screen-c-sch.txt.gz#_Jan_23_18_55_00_424738

Analysis of the issue (according to logs from Cinder scheduler):

Jan 23 18:54:11.059512 - scheduler receives status update with free_capacity_gb = 9.47
Jan 23 18:54:11.169724 - filter reports that free_capacity_gb: 9.47
Jan 23 18:54:12.503192 - filter reports that free_capacity_gb: 8.47
....
Jan 23 18:54:57.731754 - filter reports that free_capacity_gb: 0.47
Jan 23 18:55:00.424738 - Insufficient free virtual space (-10.6GB)

Value -10.6 is calculated and one of ways to get it is when backend_state.free_capacity_gb = -0.53 (https://github.com/openstack/cinder/blob/master/cinder/scheduler/filters/capacity_filter.py#L74-L142)

The next status update goes at Jan 23 18:55:05.453072 and it resets the free space value back to 9.47

To sum up: between 2 updates of capacity numbers scheduler allocates a number of volumes; each allocation reduces local value of free disk space, until it gets below 0.

This started spiking again since March 13:

https://bugs.launchpad.net/cinder/+bug/1756220

For the recent spike, my guess is this is the thing that tipped it over:

https://github.com/openstack/cinder-tempest-plugin/commit/c82162a385040fcf70444a10bae98ca3f2823bc2

There are no other related looking changes in devstack or cinder since around March 12th.

mtreinish pointed out that that test from the tempest plugin should only get loaded in certain jobs, and he's right, I was looking at this failed job:

http://logs.openstack.org/02/539702/3/check/legacy-tempest-dsvm-cells/17731a9/job-output.txt.gz

And that test isn't in there, so it must be something else.

This tempest changed merged on March 13th to rename some volume tests:

https://github.com/openstack/tempest/commit/87a069d2a0812a35248eb436583b1c6118631426

mtreinish thought that might change the test order and thus make some other volume tests run concurrently where they didn't before which could cause scheduling issues with the CapacityFilter.

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

Looking at the actual error in the logs makes me think that we need to increase the max_over_subscription_ratio configured in the gate, create a bigger backend, or reduce the speed at which we create volumes.

That or we stop deducting the full volume size in the scheduler from free_capacity_gb in the Cinder scheduler for thin provisioned volumes.

On a side note, there seems to be some other issues in the Cinder Scheduler:

- We can get to negative numbers for free_capacity_gb

- We are logging some incoherent things:

Looking at req-8cd996a1-3662-44ab-9ca2-593aa84833b3 in one of the failures [1] we would assume that the backend has more than enough space for the volume from the logged information at Mar 16 13:26:41.201266:

{'provisioned_capacity_gb': 1.0,
 'volume_backend_name': 'lvmdriver-1',
 'location_info': 'LVMVolumeDriver:ubuntu-xenial-rax-ord-0003018294:stack-volumes-lvmdriver-1:thin:0',
 'free_capacity_gb': 22.76,
 'allocated_capacity_gb': 7,
 'total_volumes': 2,
 'pool_name': 'lvmdriver-1',
 'reserved_percentage': 0,
 'max_over_subscription_ratio': '20.0',
 'total_capacity_gb': 22.8}

But that's not the actual data that is used for filtering as can be seen in the log entry of that same request at Mar 16 13:26:41.202743:

Backend: host 'ubuntu-xenial-rax-ord-0003018294@lvmdriver-1#lvmdriver-1'
free_capacity_gb: -0.23999999999999844,
total_capacity_gb: 22.8
allocated_capacity_gb: 30
max_over_subscription_ratio: 20.0
reserved_percentage: 0
provisioned_capacity_gb: 24.0

[1] http://logs.openstack.org/67/550967/4/check/tempest-full-py3/c67e31b/controller/logs/screen-c-sch.txt

Reviewed: https://review.openstack.org/553794
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=dfce8aef57ba03105459c0caff99c112ba373ad1
Submitter: Zuul
Branch: master

commit dfce8aef57ba03105459c0caff99c112ba373ad1
Author: Matt Riedemann <email address hidden>
Date: Fri Mar 16 13:48:39 2018 +0000

    Revert "Stop unnecessarily querying storage for stats"

    This reverts commit 458840ddb12164c27054413bb7a7ffcd168b614e.

    We've seen a spike in scheduling failures since this merged,
    presumably because the scheduler doesn't have the latest
    information and thinks the storage backend is at capacity.

    Change-Id: I5b6645cfd1277f315eb9cf186848d0eea8bc0b98
    Closes-Bug: #1741275

This issue was fixed in the openstack/cinder 13.0.0.0b1 development milestone.

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

I'm wondering whether this has been fixed by updating quota or if the revert that has been proposed did? Basically I have that same issue in one of my env. I proposed a fix here [0]. I think it's related on how we do compute the virtual space and make it against the requested space. Any comments would be appreciated.

[0] https://review.openstack.org/#/c/651172/