os/exec: tests break testing package if testlog file is not file descriptor 3

[siebenmann]

What version of Go are you using (go version)?

go version devel +2c0c68d621 Tue Mar 6 23:33:28 2018 +0000 linux/amd64

(This is the current git tip as I write this.)

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOOS="linux"

What did you do?

On one of my slower machines I'm getting frequent but not completely consistent test failures in the test phase of all.bash during testing of os.exec. This reproduces when testing just os/exec on its own:

$ go test os/exec
PASS
testing: can't write /tmp/go-build685356926/b001/testlog.txt: write /tmp/go-build685356926/b001/testlog.txt: broken pipe
FAIL    os/exec 0.400s

This failure happens on an i5-2500 (running Fedora 27). A Fedora 27 Ryzen 1800X machine consistently passes. This only started happening on recent versions of master (initially I wrote it off as flakiness on my machine).

It's possible that this is related to #24050.

[andybons]

/cc @ianlancetaylor

[ianlancetaylor]

This is a strange error. The file is an ordinary file, not a pipe. Why would a write fail with EPIPE? I don't see any pipe here.

Can you run running go test -c os/exec and then ./exec.test -test.short -test.testlogfile=/tmp/x? If you can recreate the problem that way, please attach the output of strace -f ./exec.test -test.short -test.testlogfile=/tmp/x. Thanks.

[siebenmann]

I don't know if I'm reproducing it, but I'm having something unusual happen:

$ ./exec.test -test.short -test.testlogfile=/tmp/x
--- FAIL: TestCatGoodAndBadFile (0.00s)
        exec_test.go:141: expected test code; got "Error: open exec_test.go: no such file or directory\n" (len 52)
FAIL
testing: can't write /tmp/x: write /tmp/x: bad file descriptor

Here is the strace output: strace-out.txt.

[siebenmann]

Okay, if I generate and run exec.test from src/os/exec, it reports that it passes and then has the testing: error. Here's the strace output for that all-passing case, in case it makes a difference:
strace-out.txt

[ianlancetaylor]

Thanks. Judging by the strace output, file descriptor 4 is already open in your environment when the process starts. The test does not expect that. Are you aware of anything that would cause the process to be started with file descriptor already open?

[siebenmann]

I'm not aware of anything in my environment that would cause file descriptor 4 to already be open, but the next time I have this test failure I'll see what lsof says about my shell's file descriptors and so on.

(However, looking at the strace output appears to show some use of file descriptor 4 when opening things, which seems odd if it's in use when the test run starts. There are quite a lot of uses of openat that return fd 4, along with eg socket and fcntl being used to duplicate fds.)

[ianlancetaylor]

Those cases where openat or socket return descriptor 4 are after a long string of close calls that close all open file descriptors starting at 4. That string of close calls is from closeUnexpectedFds in os/exec/exec_test.go. Before that string of close calls, calls to openat, etc., are returning 5, not 4.

[ianlancetaylor]

(I've been focusing on file descriptor 4 for no good reason, but it seems that file descriptor 3 is also unexpectedly open.)

[siebenmann]

I've now discovered what I do that causes the unexpectedly opened file descriptors, including the pipe. My sequence is:

1. git pull to update to the latest master
2. git log <a>...<b> to read the changes, which starts less as my pager.
3. inside less, use !xterm & to start a new xterm where I will run a build while I'm reading the changes.
4. this creates a shell inside the new xterm that has inherited already opened file descriptors from less; it appears that fd 3 is /dev/tty and fd 4 is the pipe from git.
5. start building with all.bash.

It doesn't appear to matter if the pipe has been closed by git by the time the Go build reaches testing os/exec; either way things fail.

This doesn't happen consistently because I don't always start a new xterm from inside the less. Sometimes I read everything before starting the build, and sometimes I start a new xterm from my window manager (doing that is slightly less convenient because I then have to cd to the Go source directory, which is why I often start it from inside less).

[ianlancetaylor]

I don't see a clean way to avoid this problem. Fundamentally we want to check that the file descriptor of the testlog file is 3, but I don't see a good way to find that out.

[navytux]

For the reference I'm also having this problem when building Go1.10 under SlapOS: the builder was (wrongly) leaking opened descriptor to log file and this is causing the same

testing: can't write /tmp/go-build685356926/b001/testlog.txt: write /tmp/go-build685356926/b001/testlog.txt: broken pipe

failure.

Things are now fixed on SlapOS side, but it will take time for the fix to propagate everywhere.

On the other hand for the Go side maybe it makes more sense to not assume fixed fd number for the testlog.txt file and do things similarly to how os/exec test is already checking for file descriptor used by runtime for polling:

func closeUnexpectedFds(t *testing.T, m string) {
        for fd := basefds(); fd <= 101; fd++ {
                if fd == poll.PollDescriptor() {          // <- NOTE here
                        continue
                }
                err := os.NewFile(fd, "").Close()
                if err == nil {
                        t.Logf("%s: Something already leaked - closed fd %d", m, fd)
                }
        }
}

(https://github.com/golang/go/blob/26e0e8a840/src/os/exec/exec_test.go#L415)

because after all it is a regression compared to Go1.9 which did not had this problem.

Thanks beforehand,
Kirill

[ianlancetaylor]

Unfortunately I don't think that approach will work, as the test will still fail. It will fail because the child process will see the testlog argument but will not have interpreted it so the actual testlog file will not be known. And it won't work because it will still see an unexpectedly open file descriptor, although at least in that case the error message will be more clear.

[ar4mirez]

This same issue happen to me and I found that its related with the terminal, for example I was using hyper terminal and once I tried in iterm2 and the regular mac terminal worked.

I hope this helps, cheers.

[jefferai]

Seeing this issue on an Ubuntu 18.04 machine (using Konsole, FWIW) when running the 1.11 all.bash file.

[dhobsd]

This is breaking our internal builders for our host toolchain for Fuchsia as well. Our CI/CD hooks up an extra pipe into the subprocess it calls, and there's not a lovely workaround for this.

@ianlancetaylor What if this test has an init function that runs on systems that provide /proc/self/fd and use the largest fd number returned from there? And then basefds returns that value instead of its current dance if that value is nonzero?

[dhobsd]

(Or alternatively just closed fd 3 in init.)

[dhobsd]

Oh, right, none of that works, ignore me. I'll see what I can do about closing the descriptor before running run.bash.

[coderste]

I'm getting this same error when running ./all.bash after downloading the source code following the contribution guidelines :/

Go version

go version go1.12.9 darwin/amd64

Error I'm getting is

testing: can't write /var/folders/dc/pxx2c5t503jdfy7c29qrlmp9nkvqm9/T/go-build291055610/b822/testlog.txt: write /var/folders/dc/pxx2c5t503jdfy7c29qrlmp9nkvqm9/T/go-build291055610/b822/testlog.txt: socket is not connected
FAIL    os/exec 2.471s

[ianlancetaylor]

@coderste See previous discussion; is there an open file descriptor 3 or greater while running all.bash?

[bcmills]

Is this still an issue? closeUnexpectedFds was removed in CL 206939.

[siebenmann]

I can't reproduce this with my original test (and I don't think I've seen this in general for some time). I suspect that it's gone, but maybe other people are still seeing this in their environments.

[bcmills]

and I don't think I've seen this in general for some time

The aforementioned CL was merged 2019-11-13, so that's consistent with the theory that it fixed the failure. 🙂

[ianlancetaylor]

I think this is basically the same as #35469 which we fixed. So let's call this one fixed as well. Thanks.