image import copy-image will start multiple importing threads due to race condition

Bug #1884596 reported by Dan Smith
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Glance
Fix Released
Critical
Dan Smith

Bug Description

I'm filing this bug a little prematurely because Abhi and I didn't get a chance to fully discuss it. However, looking at the code and the behavior I'm seeing due to another bug (1884587), I feel rather confident.

Especially in a situation where glance is running on multiple control plane nodes (i.e. any real-world situation), I believe there is a race condition whereby two closely-timed requests to copy an image to a store will result in two copy operations in glance proceeding in parallel. I believe this to be the case due to a common "test-and-set that isn't atomic" error.

In the API layer, glance checks that an import copy-to-store operation isn't already in progress here:

https://github.com/openstack/glance/blob/e6db0b10a703037f754007bef6f56451086850cd/glance/api/v2/images.py#L167

And if that passes, it proceeds to setup the task as a thread here:

https://github.com/openstack/glance/blob/e6db0b10a703037f754007bef6f56451086850cd/glance/api/v2/images.py#L197

which may start running immediately or sometime in the future. Once running, that code updates a property on the image to indicate that the task is running here:

https://github.com/openstack/glance/blob/e6db0b10a703037f754007bef6f56451086850cd/glance/async_/flows/api_image_import.py#L479-L484

Between those two events, if another API user makes the same request, glance will not realize that a thread is already running to complete the initial task and will start another. In a situation where a user spawns a thousand new instances to a thousand compute nodes in a single operation where the image needs copying first, it's highly plausible to have _many_ duplicate glance operations going, impacting write performance on the rbd cluster at the very least.

As evidence that this can happen, we see an abnormally extended race window because of the aforementioned bug (1884587) where we fail to update the property that indicates the task is running. In a test we see a large number of them get started, followed by a cascade of failures when they fail to update that image property, implying that many such threads are running. If this situation is allowed to happen when the property does *not* fail to update, I believe we would end up with glance copying the image to the destination in multiple threads simultaneously. That is much harder to simulate in practice in a development environment, but the other bug makes it happen every time since we never update the image property to prevent it and thus the window is long.

Abhi also brought up the case where if this race occurs on the same node, the second attempt *may* actually start copying the partial image in the staging directory to the destination, finish early, and then mark the image as "copied to $store" such that nova will attempt to use the partial image immediately, resulting in a corrupted disk and various levels of failure after that. Note that it's not clear if that's really possible or not, but I'm putting it here so the glance gurus can validate.

The use of the os_glance_importing_to_stores property to "lock" a copy to a particular store is good, except that updating that list atomically means that the above mentioned race will not have anything to check after the update to see if it was the race loser. I don't see any checks in the persistence layer to ensure that an UPDATE to the row with this property doesn't already have a given store in it, or do any kind of merge. This also leads me to worry that two parallel requests to copy an image to two different stores may result in clobbering the list of stores-in-progress and potentially also the final list of stores at rest. This is just conjecture at this point, I just haven't seen anywhere that situation is accounted for.

Revision history for this message
Abhishek Kekane (abhishek-kekane) wrote :
Download full text (6.7 KiB)

There is definitely race condition problem here, ran two different scenario and below is the observation;

Note; Image size 3 GB
Available stores; ceph:rbd,slow:file,fast:file
Scenario 1: Copy same image in two different stores using two different commands (may be 2 different users running this operation)
Steps to reproduce:
1. Create image in store fast
   $ glance image-create-via-import --container-format ami --disk-format ami --name copy-scenario-1 --file <image-file> --store fast
2. Ensure that image is active
   $ glance image-show <image-id-from-step-1> | grep status
3. Copy image in store slow
   $ glance image-import <image-id-from-step-1> --import-method copy-image --stores slow
   This will send immidiate 20X response to user and 'os_glance_importing_to_stores' will show 'slow'
   $ glance image-show <image-id-from-step-1> | grep os_glance_importing_to_stores
4. Copy image in ceph (Task 4d6e443e-4829-4e5d-9016-71a39fbcef5e)
   $ glance image-import <image-id-from-step-1> --import-method copy-image --stores ceph
     This will send immidiate 20X response to user and now 'os_glance_importing_to_stores' will overwrite 'slow' with 'ceph'

Observations with the help of g-api logs https://etherpad.opendev.org/p/glance-copy-to-store-race-scenario-logs

Step 3 Task Id is eefbd9c8-be47-4ba5-b0e2-9b44407d3234
Step 4 Task Id is 4d6e443e-4829-4e5d-9016-71a39fbcef5e

1st copy operation (copy image in slow store) will start copying file into staging area.
2nd copy operation (copy image in ceph store) will exit this step as image is already present in staging area.
2nd operation will start importing image in ceph (rbd) backend
For 1st operation, After importing image in slow store while removing it from 'os_glance_importing_to_stores' it will log below debug message;
Store slow not found in property os_glance_importing_to_stores.
At this moment image data is imported completely in slow store and it will delete the staging data from staging store (line #412), but location metadata is not updated yet.
Moment after Import task of 2nd operation of copying image-data to ceph store will also complete (line #899) and this operation will fail while deleting image data from staging area (line #920)
This will trigger revert task for 2nd operation and image-data will be deleted from ceph store only.
Image data will remain in 'slow' store but it doesn't show in image locations anymore.

Final Output:
Original image created in step 1, remains active and availble in store 'fast'
Staging area is clean
Data remians as orphan in 'slow' store (1st copy operation)

Note; Image size 1.5 GB
Available stores; ceph:rbd,slow:file,fast:file,common:file,cheap:file,reliable:file
Scenario 2: User 1 imports image in all stores with allow-failure as True and user 2 tries to copy that image in other store
Steps to reproduce:
1. Create image in all stores with allow-failure as True
   $ glance image-create-via-import --container-format ami --disk-format ami --name copy-scenario-1 --file <image-file> --all-stores True --allow-failure True
   As allow-failure is True, image status will be set to active as soon as it is imported to one of the store, say ceph
   At this moment, ...

Read more...

Changed in glance:
assignee: nobody → Abhishek Kekane (abhishek-kekane)
importance: Undecided → Critical
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to glance (master)

Related fix proposed to branch: master
Review: https://review.opendev.org/737868

Changed in glance:
status: New → In Progress
summary: - image import copy-to-store will start multiple importing threads due to
+ image import copy-image will start multiple importing threads due to
race condition
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to glance (master)

Reviewed: https://review.opendev.org/737868
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=2a51843138e27071bf84269f6b2a601b3ba9978f
Submitter: Zuul
Branch: master

commit 2a51843138e27071bf84269f6b2a601b3ba9978f
Author: Dan Smith <email address hidden>
Date: Wed Jun 24 13:06:38 2020 -0700

    Add image_set_property_atomic() helper

    This adds a new DB API method to atomically create a property on an image
    in a way that we can be sure it is created once and only once for the
    purposes of exclusion of multiple threads.

    Change-Id: Ifdb711cb241ef13eccaa5ae29a234f2fe4a52eb8
    Related-Bug: #1884596

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on glance (master)

Change abandoned by Abhishek Kekane (<email address hidden>) on branch: master
Review: https://review.opendev.org/737596
Reason: Abandoning against https://review.opendev.org/743597

Changed in glance:
assignee: Abhishek Kekane (abhishek-kekane) → Dan Smith (danms)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to glance (master)

Reviewed: https://review.opendev.org/743597
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=3f6e349d0853a9746d0d744bc3eb0b2baa1ddff9
Submitter: Zuul
Branch: master

commit 3f6e349d0853a9746d0d744bc3eb0b2baa1ddff9
Author: Dan Smith <email address hidden>
Date: Tue Jul 28 09:02:13 2020 -0700

    Implement time-limited import locking

    This attempts to provide a time-based import lock that is dependent
    on the task actually making progress. While the task is copying
    data, the task message is updated, which in turn touches the task
    updated_at time. The API will break any lock after 30 minutes of
    no activity on a stalled or dead task. The import taskflow will
    check to see if it has lost the lock at any point, and/or if its
    task status has changed and abort if so.

    The logic in more detail:

    1. API locks the image by task-id before we start the task thread, but
       before we return
    2. Import thread will check the task-id lock on the image every time it
       tries to modify the image, and if it has changed, will abort
    3. The data pipeline will heartbeat the task every minute by updating
       the task.message (bonus: we get some status)
    4. If the data pipeline heartbeat ever finds the task state to be changed
       from the expected 'processing' it will abort
    5. On task revert or completion, we drop the task-id lock from the image
    6. If something ever gets stuck or dies, the heartbeating will stop
    7. If the API gets a request for an import where the lock is held, it
       will grab the task by id (in the lock) and check the state and age.
       If the age is sufficiently old (no heartbeating) and the state is
       either 'processing' or terminal, it will mark the task as failed,
       steal the lock, and proceed.

    Lots of logging throughout any time we encounter unexpected situations.

    Closes-Bug: #1884596
    Change-Id: Icb3c1d27e9a514d96fca7c1d824fd2183f69d8b3

Changed in glance:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to glance (stable/ussuri)

Related fix proposed to branch: stable/ussuri
Review: https://review.opendev.org/748007

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to glance (stable/ussuri)

Fix proposed to branch: stable/ussuri
Review: https://review.opendev.org/748014

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to glance (stable/ussuri)

Reviewed: https://review.opendev.org/748007
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=56d01f25442a77aadc168e9fa943a5cb809f4ceb
Submitter: Zuul
Branch: stable/ussuri

commit 56d01f25442a77aadc168e9fa943a5cb809f4ceb
Author: Dan Smith <email address hidden>
Date: Wed Jun 24 13:06:38 2020 -0700

    Add image_set_property_atomic() helper

    This adds a new DB API method to atomically create a property on an image
    in a way that we can be sure it is created once and only once for the
    purposes of exclusion of multiple threads.

    Change-Id: Ifdb711cb241ef13eccaa5ae29a234f2fe4a52eb8
    Related-Bug: #1884596
    (cherry picked from commit 2a51843138e27071bf84269f6b2a601b3ba9978f)

tags: added: in-stable-ussuri
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to glance (stable/ussuri)

Reviewed: https://review.opendev.org/748014
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=055e5e790272cf6a636b07a5ff0c4c2b59351fe7
Submitter: Zuul
Branch: stable/ussuri

commit 055e5e790272cf6a636b07a5ff0c4c2b59351fe7
Author: Dan Smith <email address hidden>
Date: Tue Jul 28 09:02:13 2020 -0700

    Implement time-limited import locking

    This attempts to provide a time-based import lock that is dependent
    on the task actually making progress. While the task is copying
    data, the task message is updated, which in turn touches the task
    updated_at time. The API will break any lock after 30 minutes of
    no activity on a stalled or dead task. The import taskflow will
    check to see if it has lost the lock at any point, and/or if its
    task status has changed and abort if so.

    The logic in more detail:

    1. API locks the image by task-id before we start the task thread, but
       before we return
    2. Import thread will check the task-id lock on the image every time it
       tries to modify the image, and if it has changed, will abort
    3. The data pipeline will heartbeat the task every minute by updating
       the task.message (bonus: we get some status)
    4. If the data pipeline heartbeat ever finds the task state to be changed
       from the expected 'processing' it will abort
    5. On task revert or completion, we drop the task-id lock from the image
    6. If something ever gets stuck or dies, the heartbeating will stop
    7. If the API gets a request for an import where the lock is held, it
       will grab the task by id (in the lock) and check the state and age.
       If the age is sufficiently old (no heartbeating) and the state is
       either 'processing' or terminal, it will mark the task as failed,
       steal the lock, and proceed.

    Lots of logging throughout any time we encounter unexpected situations.

    Conflicts:
     - Changes due to policy check being missing from ussuri

    Closes-Bug: #1884596
    Change-Id: Icb3c1d27e9a514d96fca7c1d824fd2183f69d8b3
    (cherry picked from commit 3f6e349d0853a9746d0d744bc3eb0b2baa1ddff9)

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to glance (master)

Reviewed: https://review.opendev.org/749069
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=bb7774c99b263c4f54d0d126ff4ee769bb3da24c
Submitter: Zuul
Branch: master

commit bb7774c99b263c4f54d0d126ff4ee769bb3da24c
Author: Dan Smith <email address hidden>
Date: Mon Aug 31 07:35:47 2020 -0700

    Add a release note about import locking

    This adds a release note detailing the new locking behavior and criteria
    for stealing the lock.

    Related-Bug: #1884596
    Change-Id: I19c713c91794694f990f1372fda61cc2e20fac54

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to glance (stable/ussuri)

Related fix proposed to branch: stable/ussuri
Review: https://review.opendev.org/749514

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to glance (stable/ussuri)

Reviewed: https://review.opendev.org/749514
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=3880298ac932e273ab9921eb09b729bb75c8a02c
Submitter: Zuul
Branch: stable/ussuri

commit 3880298ac932e273ab9921eb09b729bb75c8a02c
Author: Dan Smith <email address hidden>
Date: Mon Aug 31 07:35:47 2020 -0700

    Add a release note about import locking

    This adds a release note detailing the new locking behavior and criteria
    for stealing the lock.

    Related-Bug: #1884596
    Change-Id: I19c713c91794694f990f1372fda61cc2e20fac54
    (cherry picked from commit bb7774c99b263c4f54d0d126ff4ee769bb3da24c)

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/glance 20.1.0

This issue was fixed in the openstack/glance 20.1.0 release.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.