race conditions between compute and schedule disk report

[jichenjc]

devstack recently built and *not* with in-tree virt layer but I think it's not related to it

got following error in conductor log

  File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 133, in _process_incoming
    res = self.dispatcher.dispatch(message)

  File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 150, in dispatch
    return self._do_dispatch(endpoint, method, ctxt, args)

  File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 121, in _do_dispatch
    result = func(ctxt, **new_args)

  File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 199, in inner
    return func(*args, **kwargs)

  File "/opt/stack/new/nova/nova/scheduler/manager.py", line 104, in select_destinations
    dests = self.driver.select_destinations(ctxt, spec_obj)

  File "/opt/stack/new/nova/nova/scheduler/filter_scheduler.py", line 53, in select_destinations
    selected_hosts = self._schedule(context, spec_obj)

  File "/opt/stack/new/nova/nova/scheduler/filter_scheduler.py", line 104, in _schedule
    hosts = self._get_all_host_states(elevated)

  File "/opt/stack/new/nova/nova/scheduler/filter_scheduler.py", line 145, in _get_all_host_states
    return self.host_manager.get_all_host_states(context)

  File "/opt/stack/new/nova/nova/scheduler/host_manager.py", line 597, in get_all_host_states
    self._get_instance_info(context, compute))

  File "/opt/stack/new/nova/nova/scheduler/host_manager.py", line 180, in update
    return _locked_update(self, compute, service, aggregates, inst_dict)

  File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
    return f(*args, **kwargs)

  File "/opt/stack/new/nova/nova/scheduler/host_manager.py", line 169, in _locked_update
    self._update_from_compute_node(compute)

  File "/opt/stack/new/nova/nova/scheduler/host_manager.py", line 201, in _update_from_compute_node
    free_disk_mb = free_gb * 1024

TypeError: unsupported operand type(s) for *: 'NoneType' and 'int'

scheduler log shows following

2016-07-27 13:45:00.934 21123 DEBUG oslo_concurrency.lockutils [req-fc02af23-3279-4c93-8732-9b4f9f3a0b8d tempest-ServersTestJSON-2014112056 tempest-ServersTestJSON-2014112056] Lock "(u'opnssi1', u'OPNSSI1')" acquired by "nova.scheduler.host_manager._locked_update" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-07-27 13:45:00.935 21123 DEBUG nova.scheduler.host_manager [req-fc02af23-3279-4c93-8732-9b4f9f3a0b8d tempest-ServersTestJSON-2014112056 tempest-ServersTestJSON-2014112056] Update host state from compute node: ComputeNode(cpu_allocation_ratio=16.0,cpu_info='{"cec_model": "2827", "architecture": "s390x"}',created_at=2016-07-27T13:45:00Z,current_workload=None,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=432,free_disk_gb=None,free_ram_mb=None,host='opnssi1',host_ip=10.32.201.222,hypervisor_hostname='OPNSSI1',hypervisor_type='zvm',hypervisor_version=630,id=2,local_gb=556,local_gb_used=124,memory_mb=24576,memory_mb_used=0,metrics=None,numa_topology=None,pci_device_pools=None,ram_allocation_ratio=10.0,running_vms=None,service_id=None,stats={},supported_hv_specs=[HVSpec],updated_at=None,uuid=366d9b37-8570-4188-8aab-bc9819cb2312,vcpus=8,vcpus_used=8) _locked_update /opt/stack/new/nova/nova/scheduler/host_manager.py:168
2016-07-27 13:45:00.936 21123 WARNING nova.scheduler.host_manager [req-fc02af23-3279-4c93-8732-9b4f9f3a0b8d tempest-ServersTestJSON-2014112056 tempest-ServersTestJSON-2014112056] Host OPNSSI1 has more disk space than database expected (432 GB > None GB)

and compute logs shows the compute node was created first time here

2016-07-27 13:45:00.396 21125 WARNING nova.compute.resource_tracker [req-1ec17be4-cc14-494b-8f88-8bce1999fba1 - -] No compute node record for opnssi1:OPNSSI1

2016-07-27 13:45:01.009 21125 INFO nova.compute.resource_tracker [req-1ec17be4-cc14-494b-8f88-8bce1999fba1 - -] Compute_service record updated for opnssi1:OPNSSI1

[jichenjc (jichenjc)]

my guessing is scheduler accessed the db record while the db is saved not fully?
should we check the updated_at before use it?

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/352317
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=36a0ba9c8141b445f2c6bfc093fde4cc98d229b2
Submitter: Jenkins
Branch: master

commit 36a0ba9c8141b445f2c6bfc093fde4cc98d229b2
Author: jichenjc <email address hidden>
Date: Sat Jul 23 23:21:39 2016 +0800

    Avoid update resource if compute node not updated

    There's a race condition that compute record might be created
    and updated through objects.compute_node.update_from_virt_driver
    function, but some fields free_disk_gb are not updated yet
    so accessing from scheduler service will find a 'None' value
    and lead to exception

    Change-Id: Ia68298a3f01d89bbf302ac734389f7282176c553
    Closes-Bug: 1610679

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/385282

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/385282
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=85fa48c008b79fe2f79274516373e66fd563850c
Submitter: Jenkins
Branch: stable/newton

commit 85fa48c008b79fe2f79274516373e66fd563850c
Author: jichenjc <email address hidden>
Date: Sat Jul 23 23:21:39 2016 +0800

    Avoid update resource if compute node not updated

    There's a race condition that compute record might be created
    and updated through objects.compute_node.update_from_virt_driver
    function, but some fields free_disk_gb are not updated yet
    so accessing from scheduler service will find a 'None' value
    and lead to exception

    Change-Id: Ia68298a3f01d89bbf302ac734389f7282176c553
    Closes-Bug: 1610679
    (cherry picked from commit 36a0ba9c8141b445f2c6bfc093fde4cc98d229b2)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/387332

[OpenStack Infra (hudson-openstack)]

Change abandoned by jichenjc (<email address hidden>) on branch: stable/mitaka
Review: https://review.openstack.org/387332
Reason: ok, got it

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 14.0.2 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 15.0.0.0b1 development milestone.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 14.0.2 release.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/416822
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=2f1245a56c238646a056a20caa543f2a254b83d7
Submitter: Jenkins
Branch: master

commit 2f1245a56c238646a056a20caa543f2a254b83d7
Author: Matt Riedemann <email address hidden>
Date: Wed Jan 4 22:06:23 2017 -0500

    Fix TypeError in _update_from_compute_node race

    A compute node record is created in the database from the
    _init_compute_node method in the resource tracker in the
    nova-compute service. It is created without the updated_at
    or free_disk_gb fields being set.

    Shortly after it's created, update_resource_stats() is called
    on the scheduler report client which calls compute_node.save()
    which calls the update_compute_node() method in the DB API which
    *always* updates the updated_at field even if nothing else
    was changed.

    So at this point, we have a compute node with updated_at set
    but not free_disk_gb. The free_disk_gb field gets set by the
    _update_usage_from_instances() method in the resource tracker
    and then that value is later saved off when the compute node
    is updated in the database on a second call to the
    update_resource_stats() method in the scheduler report client.
    At that point the free_disk_gb field is set on the compute
    node record.

    There is a race in between the compute node create and initial
    update but before free_disk_gb is set where the scheduler host
    manager can be attempting to update the HostState object from
    the same compute node when selecting host destinations during
    a server build. If that picks up the compute node before its
    free_disk_gb field is set it will result in a TypeError when
    trying to multiply None * 1024.

    Change 36a0ba9c8141b445f2c6bfc093fde4cc98d229b2 was an earlier
    attempt at fixing this bug and shortened the race window but
    didn't handle the problem where updated_at is set but free_disk_gb
    is not yet.

    This change builds on that by simply checking for the thing
    the scheduler host manager actually cares about, which is the
    free_disk_gb field.

    Closes-Bug: #1654102
    Closes-Bug: #1610679

    Change-Id: I37b75dabb3ea7ec2d5678550d9aff30b1a0c29e6

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 15.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/427080

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/427080
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=e30b75097840019c38e0619e70924ddc9f9487a0
Submitter: Jenkins
Branch: stable/newton

commit e30b75097840019c38e0619e70924ddc9f9487a0
Author: Matt Riedemann <email address hidden>
Date: Wed Jan 4 22:06:23 2017 -0500

    Fix TypeError in _update_from_compute_node race

    A compute node record is created in the database from the
    _init_compute_node method in the resource tracker in the
    nova-compute service. It is created without the updated_at
    or free_disk_gb fields being set.

    Shortly after it's created, update_resource_stats() is called
    on the scheduler report client which calls compute_node.save()
    which calls the update_compute_node() method in the DB API which
    *always* updates the updated_at field even if nothing else
    was changed.

    So at this point, we have a compute node with updated_at set
    but not free_disk_gb. The free_disk_gb field gets set by the
    _update_usage_from_instances() method in the resource tracker
    and then that value is later saved off when the compute node
    is updated in the database on a second call to the
    update_resource_stats() method in the scheduler report client.
    At that point the free_disk_gb field is set on the compute
    node record.

    There is a race in between the compute node create and initial
    update but before free_disk_gb is set where the scheduler host
    manager can be attempting to update the HostState object from
    the same compute node when selecting host destinations during
    a server build. If that picks up the compute node before its
    free_disk_gb field is set it will result in a TypeError when
    trying to multiply None * 1024.

    Change 36a0ba9c8141b445f2c6bfc093fde4cc98d229b2 was an earlier
    attempt at fixing this bug and shortened the race window but
    didn't handle the problem where updated_at is set but free_disk_gb
    is not yet.

    This change builds on that by simply checking for the thing
    the scheduler host manager actually cares about, which is the
    free_disk_gb field.

    Closes-Bug: #1654102
    Closes-Bug: #1610679

    (cherry-picked from 2f1245a56c238646a056a20caa543f2a254b83d7)
    Change-Id: I37b75dabb3ea7ec2d5678550d9aff30b1a0c29e6

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 14.0.4 release.