OSError failure to read when creating multiple instances with NFS

I have been regularly hitting this too, in a test suite (for the Calico networking driver) using Queens.

The typical pattern for me is:
- launch an instance on a compute node (which is an NFS client); this succeeds
- after 20-30s, launch another instance on the same compute node; this fails with the same call stack as above.

But I guess that's close enough for us to be talking about the same root cause here.

The biggest thing that I don't understand about this is: why aren't there loads of OpenStack users hitting this all the time? Do most OpenStack deployment using Queens or later not use NFS for instance ephemeral storage? If not, is that because they don't care about live migration, or because they're getting that some other way?

(I should add: I'm pretty sure this problem was introduced going from Pike to Queens. I run the same test suite regularly on Pike and Queens, and the Pike test never sees a problem like this; and the nova.privsep.path.utime code was introduced between Pike and Queens.)

Since yesterday I have been running my test successfully with the workaround at https://review.openstack.org/#/c/633493/. In other words, just don't worry if that utime call fails. I'd be interested to hear if you think there's anything fundamentally wrong with that; it feels to me like a simpler fix than the locking that you have proposed.

Actually, after looking at your patch in detail, s/simpler/less mysterious/ !

Hey Neil,
"The biggest thing that I don't understand about this is: why aren't there loads of OpenStack users hitting this all the time? Do most OpenStack deployment using Queens or later not use NFS for instance ephemeral storage? If not, is that because they don't care about live migration, or because they're getting that some other way?"

I wondered the same thing. I'm guessing most folks use something like Ceph for shared storage (at last users using TripleO).

Looking at your patch I think the modifying the file time is done for a reason (I cant recall what it was but I remember it was to notify some other mechanism in nova about the cache), so rather than just ignoring the failure, my patch in my testing resolves it. Did you ever try using my patch to see if the problem still happens for you?

Tim, I'm sorry, I only just noticed your comment, because I forgot to subscribe to this bug.

I believe the base file time is modified so that the image cache manager knows that that base image was recently in use. (The "image cache manager" is actually an image garbage collector, IIUC.)

I haven't tried your patch instead of mine yet. I'll aim to do that next week, and will report back here.

Tim - just wanted to let you know that I've today been able to test that your fix (as at https://review.openstack.org/#/c/625741/2) seems reliably successful with my team's system testing. I've run system tests with your fix for about 15 hours today, and they were all successful. (I'll comment this on the change as well.)

Reviewed: https://review.openstack.org/625741
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=525631d8dc058910728e55def616358b0e7f2f69
Submitter: Zuul
Branch: master

commit 525631d8dc058910728e55def616358b0e7f2f69
Author: Tim Rozet <email address hidden>
Date: Mon Dec 17 19:44:54 2018 -0500

    Fixes race condition with privsep utime

    There is a race condition that occurs over NFS when multiple instances
    are being created where utime fails, due to some other process
    modifying the file path. This patch ensures the path is created and
    is readable before attempting to modify with utime.

    Closes-Bug: 1809123

    Change-Id: Id68aa27a8ab08d9c00655e5ed6b48d194aa8e6f6
    Signed-off-by: Tim Rozet <email address hidden>

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/641023

Reviewed: https://review.openstack.org/641315
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=362bba9011f8445285c3f72a0b00630163bfbc2f
Submitter: Zuul
Branch: master

commit 362bba9011f8445285c3f72a0b00630163bfbc2f
Author: Neil Jerram <email address hidden>
Date: Sat Jan 26 21:22:33 2019 +0000

    Allow utime call to fail on qcow2 image base file

    This utime call sometimes fails, with EACCES (Permission Denied), when
    the base file is on an NFS client filesystem. I don't understand why,
    but wonder if it's a similar problem as the one that motivated using
    touch instead of utime in ec9d5e375e2. In any case, IIUC, timing
    isn't the primary thing that the image cache manager uses to determine
    when the base file is in use. The primary mechanism for that is
    whether there is a matching disk file for a current instance. The
    timestamp on the base file is only used when deciding whether to
    delete a base file that is _not_ in use; so it is not a big deal if
    that deletion happens slightly earlier, for an unused base file,
    because of one of these preceding utime calls having failed.

    Closes-Bug: #1809123
    Co-Authored-By: Matthew Booth <email address hidden>
    Change-Id: Idc131ff426f1707150867030fa5a69b77a7fc832

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

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/642998

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/643011

Change abandoned by Matt Riedemann (<email address hidden>) on branch: stable/rocky
Review: https://review.openstack.org/642998
Reason: Proper backport is here:

https://review.openstack.org/#/c/643011/

Change abandoned by Matt Riedemann (<email address hidden>) on branch: stable/queens
Review: https://review.openstack.org/642997
Reason: Fixing up the cherry pick here:

https://review.openstack.org/#/c/633493/

Change abandoned by Matt Riedemann (<email address hidden>) on branch: stable/rocky
Review: https://review.openstack.org/641023

Reviewed: https://review.openstack.org/643011
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=7d0dd625d35a08d159b50154809a53e8444ae25c
Submitter: Zuul
Branch: stable/rocky

commit 7d0dd625d35a08d159b50154809a53e8444ae25c
Author: Neil Jerram <email address hidden>
Date: Sat Jan 26 21:22:33 2019 +0000

    Allow utime call to fail on qcow2 image base file

    This utime call sometimes fails, with EACCES (Permission Denied), when
    the base file is on an NFS client filesystem. I don't understand why,
    but wonder if it's a similar problem as the one that motivated using
    touch instead of utime in ec9d5e375e2. In any case, IIUC, timing
    isn't the primary thing that the image cache manager uses to determine
    when the base file is in use. The primary mechanism for that is
    whether there is a matching disk file for a current instance. The
    timestamp on the base file is only used when deciding whether to
    delete a base file that is _not_ in use; so it is not a big deal if
    that deletion happens slightly earlier, for an unused base file,
    because of one of these preceding utime calls having failed.

    Closes-Bug: #1809123
    Co-Authored-By: Matthew Booth <email address hidden>
    Change-Id: Idc131ff426f1707150867030fa5a69b77a7fc832
    (cherry picked from commit 362bba9011f8445285c3f72a0b00630163bfbc2f)

This issue was fixed in the openstack/nova 19.0.0.0rc1 release candidate.

Reviewed: https://review.openstack.org/633493
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=2b1544390cd0afd4d2b0c6ea4636a49a73b50dcf
Submitter: Zuul
Branch: stable/queens

commit 2b1544390cd0afd4d2b0c6ea4636a49a73b50dcf
Author: Neil Jerram <email address hidden>
Date: Sat Jan 26 21:22:33 2019 +0000

    Allow utime call to fail on qcow2 image base file

    This utime call sometimes fails, with EACCES (Permission Denied), when
    the base file is on an NFS client filesystem. I don't understand why,
    but wonder if it's a similar problem as the one that motivated using
    touch instead of utime in ec9d5e375e2. In any case, IIUC, timing
    isn't the primary thing that the image cache manager uses to determine
    when the base file is in use. The primary mechanism for that is
    whether there is a matching disk file for a current instance. The
    timestamp on the base file is only used when deciding whether to
    delete a base file that is _not_ in use; so it is not a big deal if
    that deletion happens slightly earlier, for an unused base file,
    because of one of these preceding utime calls having failed.

    Conflicts:
          nova/tests/unit/virt/libvirt/test_imagebackend.py

    NOTE(mriedem): Conflict is due to not having change
    I154b1ef14dbace803841cb3eed3ff02dd0020588 in Queens.

    Closes-Bug: #1809123
    Co-Authored-By: Matthew Booth <email address hidden>
    Change-Id: Idc131ff426f1707150867030fa5a69b77a7fc832
    (cherry picked from commit 362bba9011f8445285c3f72a0b00630163bfbc2f)
    (cherry picked from commit 7d0dd625d35a08d159b50154809a53e8444ae25c)

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

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