cmd/go: "fork/exec foo.test: text file busy" flakes

[mdempsky]

While trybotting https://go-review.googlesource.com/c/go/+/70151, I got this flake https://storage.googleapis.com/go-build-log/c8965fb8/openbsd-amd64-60_817d939c.log;

fork/exec /tmp/go-build452069409/b118/jsonrpc.test: text file busy
FAIL	net/rpc/jsonrpc	0.003s

Maybe recent cmd/go work?

/cc @rsc

[eliasnaur]

A similar one from a linux/386 trybot:

https://storage.googleapis.com/go-build-log/a1da169f/linux-386_2279a6a1.log

fork/exec /tmp/go-build989750233/b052/ecdsa.test: text file busy
FAIL	crypto/ecdsa	0.001s

[aclements]

Almost certainly related to the recent cmd/go changes. Russ is looking into it.

$ greplogs -dashboard -e "text file busy" -l | findflakes -paths
First observed cdbc363 11 Oct 19:03 2017 (24 commits ago)
Last observed  c37647f 12 Oct 07:12 2017 (2 commits ago)
30% chance failure is still happening
45% failure probability (11 of 23 commits)
Likely culprits:
   45% cdbc363 cmd/go: record both build ID and content ID in archives and binaries
   25% 85f93c8 cmd/compile: fix some plive comments
   14% e130dcf cmd/compile: abort earlier if stack frame too large
    7% 624630b cmd/compile: fold constant comparisions into SETxxmem ops.
No known past failures

It's not really clear how cdbc363 could actually be causing this, though.

[rsc]

Makes no sense. I did have a missing f.Close, but on a file open for reading, not writing. The close of the file open for writing seems obviously there:

w, err := os.OpenFile(target, os.O_WRONLY, 0)
if err != nil {
	return err
}
err = buildid.Rewrite(w, matches, newID)
if err != nil {
	w.Close()
	return err
}
if err := w.Close(); err != nil {
	return err
}

I am wondering if a child process is inheriting the file descriptor and so it stays open in the child after we close it, but os.OpenFile adds O_CLOEXEC, which should make that impossible.

Trying to reproduce. I could just bypass that code path entirely for binaries we are going to run and discard. I assume that would fix the problem, but I'd like to understand the actual problem first.

[rsc]

Reproduced with

while go test -short encoding/...; do true; done

on my Mac. The code in question is not actually needed for ephemeral binaries, like the ones that go test runs, so I'll probably just disable it without understanding it and move on.

[rsc]

It occurs to me that this would happen if os.File.Close returned before the fd had actually been closed. @ianlancetaylor and I have been talking about things like this related to net.Conns, but since the use of the writable fd here is single-threaded, I don't see how the close would not be complete at the moment the test runs.

[gopherbot]

Change https://golang.org/cl/70390 mentions this issue: cmd/go: do not rewrite build ID in ephemeral binaries

[rsc]

If anyone can make this happen reliably - like five times in a row in a given time period reliably - then please patch in CL 70390 and see how that changes the frequency at which it happens.

I've somehow lost the ability to reproduce this on my Mac in an unmodified client, so I can't see whether CL 70390 makes the situation better. I did, however, see the problem happen once on my Mac even with CL 70390 applied, so it doesn't appear to be a complete fix regardless.

It should be safe, though, so if anyone can demonstrate proof that it helps, it's fine to submit.

[rsc]

I got this to happen once on Linux using 'perf trace record'. Here is the trace - trace1.txt.gz - truncated right after the exec that got ETXTBSY. Literally every open call in the trace has CLOEXEC set.

But maybe the problem is that there is a separate fork+exec happening in parallel, and while that separate child's exec will close the writable fd, it hasn't exec'ed yet, so it still holds the fd in its forked copy of the fd tables. That would explain the problem. It would not explain why I saw this even after removing the "open binary for write" code from my Mac, but maybe there is a second problem on the Mac.

Now that I got a trace on Linux with the old code I will try with my pending CL.

[rsc]

Backing up a step. On systems where close(2) actually does real work and can return a meaningful error, does that only apply to the final close of the underlying file? That is, if I do:

fd = open()
write(fd)
fd2 = dup(fd)
close(fd)
close(fd2)

Does the close(fd) do any real work flushing writes, or is it only the close(fd2)? Because if it's only the close(fd2), then any time you have a file open for write and have a different goroutine doing fork+exec, there's a race where you might not see write errors because your close is not the last. The other goroutine can do a fork (essentially creating fd2 as above), and then close(fd) does nothing - and succeeds - because fd2 is still open, and then the new child process either execs or exits and closes fd2 implicitly.

Are things really this bad?

The same logic means that cmd/go basically can never open an executable for write. It must always invoke a subprocess to do that, because if it opens an executable for write there is no guarantee about a timely close of the fd relative to a future attempted exec.

Are things really this bad?

/cc @ianlancetaylor @aclements

[crawshaw]

My understanding is the first close does serious work. I base this on the fact that the first close will release any process-wide file system locks, even when there are other descriptors. (I went and looked in the linux kernel sources to confirm, and did find an unconditional call to a flush op on the close path, but I couldn't follow it into a file system implementation.)

Unfortunately, I can't nail down what serious work is. It is definitely FS-specific, but I haven't found any notes about what is conventional for "fast" file systems. It sounds like it flushes to the kernel write buffers. The syscall documentation explicitly says it does not push the changes to physical media:

   A successful close does not guarantee that the data has been
   successfully saved to disk, as the kernel uses the buffer cache to
   defer writes.  Typically, filesystems do not flush buffers when a
   file is closed.  If you need to be sure that the data is physically
   stored on the underlying disk, use fsync(2).  (It will depend on the
   disk hardware at this point.)

But that doesn't say anything about the visibility of the changes to other processes.

There is also this alarming note:

   It is probably unwise to close file descriptors while they may be in
   use by system calls in other threads in the same process.  Since a
   file descriptor may be reused, there are some obscure race conditions
   that may cause unintended side effects.

http://man7.org/linux/man-pages/man2/close.2.html

It is not clear if this applies to close-on-exec descriptors. If it does, then syscall.Close should grab a read lock on runtime.execLock.

None of that really helps though, sorry.

[bradfitz]

It is not clear if this applies to close-on-exec descriptors. If it does, then syscall.Close should grab a read lock on runtime.execLock.

That's an easy enough experiment to see if it helps, though, assuming this is reproducible enough.