t0032 fails on NFS mounts

Hi-

I've checked out "maint".

Unit test t0032 fails when run on an NFS mount:

[vagrant@cel t]$ ./t0032-reftable-unittest.sh not ok 1 - unittests # # TMPDIR=$(pwd) && export TMPDIR && # test-tool reftable # # failed 1 among 1 test(s) 1..1 [vagrant@cel t]$

But not on XFS:

[vagrant@cel t]$ ./t0032-reftable-unittest.sh ok 1 - unittests # passed all 1 test(s) 1..1 [vagrant@cel t]$ cd .. [vagrant@cel git]$ ./git --version git version 2.44.0 [vagrant@cel git]$

v2.43.2 seems to work OK.

On Tuesday, March 12, 2024 11:10 AM, Chuck Lever wrote:

1 test(s)

I have seen a similar effect on a standard POSIX file system (NonStop) when run in a special platform container (Pathway). It does not happen for me when run from bash directly. This may be something other than an NFS effect, or unrelated to what I observed. I'll be monitoring this sub-test for repeats. --Randall

On Tue, Mar 12, 2024 at 01:11:15PM -0400, rsbecker@nexbridge.com wrote:

Interesting. Do you know at what point in time this happened? Was it for one of the releases or any of the in-between states? Also, does Pathway mess with the stat(3P) info somehow?

Patrick

+cc Patrick for reftable

On Tue, Mar 12, 2024 at 11:10:29AM -0400, Chuck Lever wrote:

The output for this test script is particularly unhelpful because it's not using our test harness at all, but just running a bunch of internal tests using a single program.

Running with "-v" should give more details about what's failing.

I set up a basic loopback server like:

  mkdir /mnt/{server,client}
  exportfs -o rw,sync 127.0.0.1:/mnt/server
  mount -t nfs 127.0.0.1:/mnt/server /mnt/client

and then ran:

  ./t0032-reftable-unittest.sh --root=/mnt/client -v

Looks like it fails at:

  running test_reftable_stack_compaction_concurrent_clean
  reftable/stack_test.c: 1063: failed assertion count_dir_entries(dir) == 2
  Aborted

For me, too. Bisecting shows the problem appearing in 4f36b8597c (reftable/stack: fix race in up-to-date check, 2024-01-18).

-Peff

PS That test seems to run ~20x slower on NFS versus directly on ext4.
   I'd expect a little overhead, but that's quite a bit.

On Wed, Mar 13, 2024 at 03:20:52AM -0400, Jeff King wrote:

Unless somebody else beats me to it I'll investigate this next week when I'm back in the office. Thanks for the report and for digging into this issue!

Patrick

Patrick Steinhardt <ps@pks.im> writes:

Thanks.

On Wed, Mar 13, 2024 at 03:20:52AM -0400, Jeff King wrote:

I think this is actually benign. I set a breakpoint in the respective test right before double-checking our conditions, and curiously I got back the following list of files:

    ./stack_test-1027.QJBpnd
    ./stack_test-1027.QJBpnd/0x000000000001-0x000000000003-dad7ac80.ref
    ./stack_test-1027.QJBpnd/.nfs000000000001729f00001e11
    ./stack_test-1027.QJBpnd/tables.list

Notice the ".nfs*" thing? This is a temporary file managed by the NFS client that maintains delete-on-close behaviour because we have unlinked the file while it was still open [1]. But of course we count that file when executing `count_dir_entries()`, and thus we arrive at an unexpected number of files.

I will send a patch to fix the test.

I'm not all that surprised here given that the reftable library is quite prone to stat(3P)ing the "tables.list" file, and potentially re-reading it. I kind of suspect that this is what's going on. An alternative explanation might be that mmap'ing over NFS is really slow.

Anyway, I will have a deeper look at this and see where we spend all the time.

Patrick

[1]: https://nfs.sourceforge.net/#faq_d2

It was reported that the reftable unit tests in t0032 fail with the following assertion when running on top of NFS:

    running test_reftable_stack_compaction_concurrent_clean
    reftable/stack_test.c: 1063: failed assertion count_dir_entries(dir) == 2
    Aborted

Setting a breakpoint immediately before the assertion in fact shows the following list of files:

    ./stack_test-1027.QJBpnd
    ./stack_test-1027.QJBpnd/0x000000000001-0x000000000003-dad7ac80.ref
    ./stack_test-1027.QJBpnd/.nfs000000000001729f00001e11
    ./stack_test-1027.QJBpnd/tables.list

Note the weird ".nfs*" file? This file is maintained by NFS clients in order to emulate delete-after-last-close semantics that we rely on in the reftable code [1]. Instead of unlinking the file right away and keeping it open in the client, the NFS client will rename it to ".nfs*" and then delete that temporary file when the last reference to it gets dropped. Quoting the NFS FAQ:

    > D2. What is a "silly rename"? Why do these .nfsXXXXX files keep
    > showing up?
    >
    > A. Unix applications often open a scratch file and then unlink it.
    > They do this so that the file is not visible in the file system name
    > space to any other applications, and so that the system will
    > automatically clean up (delete) the file when the application exits.
    > This is known as "delete on last close", and is a tradition among
    > Unix applications.
    >
    > Because of the design of the NFS protocol, there is no way for a
    > file to be deleted from the name space but still remain in use by an
    > application. Thus NFS clients have to emulate this using what
    > already exists in the protocol. If an open file is unlinked, an NFS
    > client renames it to a special name that looks like ".nfsXXXXX".
    > This "hides" the file while it remains in use. This is known as a
    > "silly rename." Note that NFS servers have nothing to do with this
    > behavior.

This of course throws off the assertion that we got exactly two files in that directory.

The test in question triggers this behaviour by holding two open file descriptors to the "tables.list" file. One of the references is because we are about to append to the stack, whereas the other reference is because we want to compact it. As the compaction has just finished we already rewrote "tables.list" to point to the new contents, but the other file descriptor pointing to the old version is still open. Thus we trigger the delete-after-last-close emulation.

Furthermore, it was reported that this behaviour only triggers with 4f36b8597c (reftable/stack: fix race in up-to-date check, 2024-01-18). This is expected as well because it is the first point in time where we actually keep the "tables.list" file descriptor open for the stat cache.

Fix this bug by skipping over any files that start with a leading dot when counting files. While we could explicitly check for a prefix of ".nfs", other network file systems like SMB for example do the same trickery but with a ".smb" prefix. In any case though, this loosening of the assertion should be fine given that the reftable library would never write files with leading dots by itself.

[1]: https://nfs.sourceforge.net/#faq_d2

Reported-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: Patrick Steinhardt <ps@pks.im>
---
 reftable/stack_test.c | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

Patrick Steinhardt <ps@pks.im> writes:

Sounds good. We should count what we positively consider what we wrote, not random cruft somebody else might have dropped in the directory, and this is a good first thing to do.

Will queue.  Thanks.

Patrick Steinhardt <ps@pks.im> writes:

I'm fully supportive of this, as this will also fix any issues possibly caused by .DS_Store files created by Finder on macOS, although it's very unlikely they will be created in these tests.

-- Toon