update_available_resource_for_node racing instance deletion

Another example on stable/ocata :

http://logs.openstack.org/30/431530/1/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/b5e565e/logs/screen-n-cpu.txt.gz?level=ERROR#_2017-02-09_14_14_09_377

The logs are gone. What did this actually look like? Can you find a version of it on stable/ocata and paste the actual error in here?

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

We still see this in CI runs periodically:

http://logs.openstack.org/70/552170/2/check/legacy-tempest-dsvm-multinode-live-migration/474e6b5/logs/screen-n-cpu.txt.gz?level=INFO#_Mar_13_22_24_03_425580

We can see that in this case, the instance in question has it's files deleted right before the libvirt driver, via the update_available_resource periodic task, gets to processing that instance:

Mar 13 22:24:03.367217 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: INFO nova.virt.libvirt.driver [None req-d0181533-0010-4268-bea5-fda2a392e8f1 tempest-LiveMigrationRemoteConsolesV26Test-2100428245 tempest-LiveMigrationRemoteConsolesV26Test-2100428245] [instance: 0460cf87-16f1-4aa3-a964-7cab159327dc] Deleting instance files /opt/stack/data/nova/instances/0460cf87-16f1-4aa3-a964-7cab159327dc_del
Mar 13 22:24:03.367725 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: INFO nova.virt.libvirt.driver [None req-d0181533-0010-4268-bea5-fda2a392e8f1 tempest-LiveMigrationRemoteConsolesV26Test-2100428245 tempest-LiveMigrationRemoteConsolesV26Test-2100428245] [instance: 0460cf87-16f1-4aa3-a964-7cab159327dc] Deletion of /opt/stack/data/nova/instances/0460cf87-16f1-4aa3-a964-7cab159327dc_del complete
Mar 13 22:24:03.425580 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: ERROR nova.compute.manager [None req-d0181533-0010-4268-bea5-fda2a392e8f1 tempest-LiveMigrationRemoteConsolesV26Test-2100428245 tempest-LiveMigrationRemoteConsolesV26Test-2100428245] Error updating resources for node ubuntu-xenial-rax-iad-0002937850.: InvalidDiskInfo: Disk info file is invalid: qemu-img failed to execute on /opt/stack/data/nova/instances/0460cf87-16f1-4aa3-a964-7cab159327dc/disk : Unexpected error while running command.
Mar 13 22:24:03.425969 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: Command: /usr/bin/python2 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/0460cf87-16f1-4aa3-a964-7cab159327dc/disk --force-share
Mar 13 22:24:03.426340 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: Exit code: 1
Mar 13 22:24:03.426705 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: Stdout: u''
Mar 13 22:24:03.427044 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: Stderr: u"qemu-img: Could not open '/opt/stack/data/nova/instances/0460cf87-16f1-4aa3-a964-7cab159327dc/disk': Could not open '/opt/stack/data/nova/instances/0460cf87-16f1-4aa3-a964-7cab159327dc/disk': No such file or directory\n"
Mar 13 22:24:03.427380 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: ERROR nova.compute.manager Traceback (most recent call last):
Mar 13 22:24:03.427724 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/manager.py", line 7320, in update_available_resource_for_node
Mar 13 22:24:03.428084 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: ERROR nova.compute.manager rt.update_available_resource(context, nodename)
Mar 13 22:24:03.428410 ubuntu-xenial-rax-iad-0002937850 nova-compute[30634]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 664, in update_available_resour...

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22InvalidDiskInfo%5C%22%20AND%20message%3A%5C%22qemu-img%3A%20Could%20not%20open%5C%22%20AND%20message%3A%5C%22No%20such%20file%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=7d

20 hits in 7 days.

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

Reviewed: https://review.openstack.org/553067
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=5f16e714f58336344752305f94451e7c7c55742c
Submitter: Zuul
Branch: master

commit 5f16e714f58336344752305f94451e7c7c55742c
Author: Matt Riedemann <email address hidden>
Date: Wed Mar 14 16:43:22 2018 -0400

    libvirt: handle DiskNotFound during update_available_resource

    The update_available_resource periodic task in the compute manager
    eventually calls through to the resource tracker and virt driver
    get_available_resource method, which gets the guests running on
    the hypervisor, and builds up a set of information about the host.
    This includes disk information for the active domains.

    However, the periodic task can race with instances being deleted
    concurrently and the hypervisor can report the domain but the driver
    has already deleted the backing files as part of deleting the
    instance, and this leads to failures when running "qemu-img info"
    on the disk path which is now gone.

    When that happens, the entire periodic update fails.

    This change simply tries to detect the specific failure from
    'qemu-img info' and translate it into a DiskNotFound exception which
    the driver can handle. In this case, if the associated instance is
    undergoing a task state transition such as moving to another host or
    being deleted, we log a message and continue. If the instance is in
    steady state (task_state is not set), then we consider it a failure
    and re-raise it up.

    Note that we could add the deleted=False filter to the instance query
    in _get_disk_over_committed_size_total but that doesn't help us in
    this case because the hypervisor says the domain is still active
    and the instance is not actually considered deleted in the DB yet.

    Change-Id: Icec2769bf42455853cbe686fb30fda73df791b25
    Closes-Bug: #1662867

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

Fix proposed to branch: stable/queens
Review: https://review.openstack.org/571424

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/571426

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/571432

Reviewed: https://review.openstack.org/571424
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=5a4c6913a37f912489543abd5e12a54feeeb89e2
Submitter: Zuul
Branch: stable/queens

commit 5a4c6913a37f912489543abd5e12a54feeeb89e2
Author: Matt Riedemann <email address hidden>
Date: Wed Mar 14 16:43:22 2018 -0400

    libvirt: handle DiskNotFound during update_available_resource

    The update_available_resource periodic task in the compute manager
    eventually calls through to the resource tracker and virt driver
    get_available_resource method, which gets the guests running on
    the hypervisor, and builds up a set of information about the host.
    This includes disk information for the active domains.

    However, the periodic task can race with instances being deleted
    concurrently and the hypervisor can report the domain but the driver
    has already deleted the backing files as part of deleting the
    instance, and this leads to failures when running "qemu-img info"
    on the disk path which is now gone.

    When that happens, the entire periodic update fails.

    This change simply tries to detect the specific failure from
    'qemu-img info' and translate it into a DiskNotFound exception which
    the driver can handle. In this case, if the associated instance is
    undergoing a task state transition such as moving to another host or
    being deleted, we log a message and continue. If the instance is in
    steady state (task_state is not set), then we consider it a failure
    and re-raise it up.

    Note that we could add the deleted=False filter to the instance query
    in _get_disk_over_committed_size_total but that doesn't help us in
    this case because the hypervisor says the domain is still active
    and the instance is not actually considered deleted in the DB yet.

    Change-Id: Icec2769bf42455853cbe686fb30fda73df791b25
    Closes-Bug: #1662867
    (cherry picked from commit 5f16e714f58336344752305f94451e7c7c55742c)

Reviewed: https://review.openstack.org/571426
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=d251b95083731829ba104dc5c7f642dd5097d510
Submitter: Zuul
Branch: stable/pike

commit d251b95083731829ba104dc5c7f642dd5097d510
Author: Matt Riedemann <email address hidden>
Date: Wed Mar 14 16:43:22 2018 -0400

    libvirt: handle DiskNotFound during update_available_resource

    The update_available_resource periodic task in the compute manager
    eventually calls through to the resource tracker and virt driver
    get_available_resource method, which gets the guests running on
    the hypervisor, and builds up a set of information about the host.
    This includes disk information for the active domains.

    However, the periodic task can race with instances being deleted
    concurrently and the hypervisor can report the domain but the driver
    has already deleted the backing files as part of deleting the
    instance, and this leads to failures when running "qemu-img info"
    on the disk path which is now gone.

    When that happens, the entire periodic update fails.

    This change simply tries to detect the specific failure from
    'qemu-img info' and translate it into a DiskNotFound exception which
    the driver can handle. In this case, if the associated instance is
    undergoing a task state transition such as moving to another host or
    being deleted, we log a message and continue. If the instance is in
    steady state (task_state is not set), then we consider it a failure
    and re-raise it up.

    Note that we could add the deleted=False filter to the instance query
    in _get_disk_over_committed_size_total but that doesn't help us in
    this case because the hypervisor says the domain is still active
    and the instance is not actually considered deleted in the DB yet.

    Change-Id: Icec2769bf42455853cbe686fb30fda73df791b25
    Closes-Bug: #1662867
    (cherry picked from commit 5f16e714f58336344752305f94451e7c7c55742c)
    (cherry picked from commit 5a4c6913a37f912489543abd5e12a54feeeb89e2)

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

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

Reviewed: https://review.openstack.org/571432
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=e0c7d6c8816d0c21b2913adc7a3d6cbd59604cd0
Submitter: Zuul
Branch: stable/ocata

commit e0c7d6c8816d0c21b2913adc7a3d6cbd59604cd0
Author: Matt Riedemann <email address hidden>
Date: Wed Mar 14 16:43:22 2018 -0400

    libvirt: handle DiskNotFound during update_available_resource

    The update_available_resource periodic task in the compute manager
    eventually calls through to the resource tracker and virt driver
    get_available_resource method, which gets the guests running on
    the hypervisor, and builds up a set of information about the host.
    This includes disk information for the active domains.

    However, the periodic task can race with instances being deleted
    concurrently and the hypervisor can report the domain but the driver
    has already deleted the backing files as part of deleting the
    instance, and this leads to failures when running "qemu-img info"
    on the disk path which is now gone.

    When that happens, the entire periodic update fails.

    This change simply tries to detect the specific failure from
    'qemu-img info' and translate it into a DiskNotFound exception which
    the driver can handle. In this case, if the associated instance is
    undergoing a task state transition such as moving to another host or
    being deleted, we log a message and continue. If the instance is in
    steady state (task_state is not set), then we consider it a failure
    and re-raise it up.

    Note that we could add the deleted=False filter to the instance query
    in _get_disk_over_committed_size_total but that doesn't help us in
    this case because the hypervisor says the domain is still active
    and the instance is not actually considered deleted in the DB yet.

    Conflicts:
            nova/virt/libvirt/driver.py
            nova/tests/unit/virt/libvirt/test_driver.py

    NOTE(lyarwood): Conflicts due to the substantial refactoring of
    _get_instance_disk_info via I9616a602ee0605f7f1dc1f47b6416f01895e025b
    and removal of _LW etc during Pike,

    Change-Id: Icec2769bf42455853cbe686fb30fda73df791b25
    Closes-Bug: #1662867
    (cherry picked from commit 5f16e714f58336344752305f94451e7c7c55742c)
    (cherry picked from commit 5a4c6913a37f912489543abd5e12a54feeeb89e2)
    (cherry picked from commit d251b95083731829ba104dc5c7f642dd5097d510)

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

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