os/exec: TestExtraFilesRace flake on plan9 since 2022-11-16

[millerresearch]

#!watchflakes
post <- pkg == "os/exec" && test == "TestExtraFilesRace" && goos == "plan9"

On the plan9-arm builder the os/exec test sometimes fails like this:

--- FAIL: TestExtraFilesRace (0.50s)
    exec_test.go:850: iteration 2, process B got:
        
        want:
        fd3: listener 127.0.0.1:40881
        
FAIL
FAIL	os/exec	1.262s

This has been seen since 2022-11-16 (earliest log here).

The last change to TextExtraFilesRace before that date was the addition of t.Parallel() in CL 439196. The comment for that change says

Tests that use Setenv or Chdir or check for FDs opened during the test
still cannot be parallelized,

@bcmills, I haven't looked deeply into this but it does seem a FD is being opened during the test - is this a potential trouble spot?

I have managed to replicate the error by running go tool dist test go_test:net/url go_test:os go_test:os/exec enough times. If I remove the t.Parallel(), the error seems not to occur.

[bcmills]

I haven't looked deeply into this but it does seem a FD is being opened during the test - is this a potential trouble spot?

If I'm reading correctly, it's the opposite: we expect the subprocess to print an address for FD 3 (for the listener opened with lb := listen()), but for some reason cmdDescribeFiles in the subprocess fails to wrap it in a net.FileListener.

[bcmills]

greplogs -l -e '\Aplan9.*(\n.*)*FAIL: TestExtraFilesRace' --since=2022-01-01
2022-12-05T22:01:50-185e1a7/plan9-arm
2022-12-05T16:41:48-ad55b87/plan9-arm
2022-12-02T23:40:37-c0497d1/plan9-arm
2022-12-01T21:00:47-cd133ab/plan9-arm
2022-11-28T16:06:53-76ec47e/plan9-arm
2022-11-24T03:05:33-7a9ce74/plan9-arm
2022-11-23T19:34:12-a8510f9/plan9-arm
2022-11-22T18:52:58-21015cf/plan9-arm
2022-11-21T22:16:06-995c0f3/plan9-arm
2022-11-21T16:19:15-d7812ab/plan9-arm
2022-11-21T15:06:26-8614c52/plan9-arm
2022-11-18T22:32:44-c824448/plan9-arm
2022-11-18T21:12:24-dccc58e/plan9-arm
2022-11-18T17:59:44-b2faff1/plan9-arm
2022-11-18T14:08:47-349d398/plan9-arm
2022-11-17T18:53:13-5f7abec/plan9-arm
2022-11-17T18:24:36-217ed95/plan9-arm
2022-11-16T23:17:58-6d0bf43/plan9-arm
2022-11-16T21:42:58-52d9e41/plan9-arm
2022-11-16T21:35:23-898d000/plan9-arm
2022-09-13T17:41:06-6f7c9ea/plan9-arm

[bcmills]

The one on 2022-09-13 has a funky failure mode, which suggests the regression happened on or about 2022-11-16.

[bcmills]

(Note that I added the call to t.Parallel() in that test in CL 439196, merged 2022-10-10.)

[millerresearch]

The one on 2022-09-13 has a funky failure mode

Errors like "/boot/workdir/... does not exist' are evidence of a flake in the underlying Plan 9 filesystem, not specifically relevant to this issue.

[millerresearch]

for some reason cmdDescribeFiles in the subprocess fails to wrap it in a net.FileListener.

The error returned from the attempt to wrap it is file+net fd3: fd2path: fd out of range or not open

[bcmills]

That suggests perhaps a problem in either syscall.StartProcess (failing to actually forward the extra FD) or (*net.TCPListener).File (silently failing to produce a valid FD, or producing a duplicate?).

[gopherbot]

Change https://go.dev/cl/457115 mentions this issue: syscall: fix closing of reordered FDs in plan9 ForkExec

[millerresearch]

That suggests perhaps a problem in either syscall.StartProcess (failing to actually forward the extra FD)

You're right, a logic error was sometimes causing the newly dup'ed FD to be closed.

[bcmills]

suggests the regression happened on or about 2022-11-16.

That turned out to be off by 10½ years. 😅

(Based on the fix CL, it appears that FD forwarding on plan9 has been subtly broken ~forever, but the specific bug here was part of an attempted fix for a related bug in CL 6009046.)

[gopherbot]

Found new dashboard test flakes for:

    #!watchflakes
    post <- pkg == "os/exec" && test == "TestExtraFilesRace" && goos == "plan9"

2022-12-01 21:00 plan9-arm go@cd133abc os/exec.TestExtraFilesRace (log)

--- FAIL: TestExtraFilesRace (0.48s)
    exec_test.go:847: iteration 2, process A got:

        want:
        fd3: listener 127.0.0.1:49573

2022-12-02 23:40 plan9-arm go@c0497d1a os/exec.TestExtraFilesRace (log)

--- FAIL: TestExtraFilesRace (0.49s)
    exec_test.go:850: iteration 2, process B got:

        want:
        fd3: listener 127.0.0.1:36814

2022-12-05 16:41 plan9-arm go@ad55b878 os/exec.TestExtraFilesRace (log)

--- FAIL: TestExtraFilesRace (0.50s)
    exec_test.go:847: iteration 0, process A got:

        want:
        fd3: listener 127.0.0.1:48597

2022-12-05 22:01 plan9-arm go@185e1a7b os/exec.TestExtraFilesRace (log)

--- FAIL: TestExtraFilesRace (0.50s)
    exec_test.go:850: iteration 2, process B got:

        want:
        fd3: listener 127.0.0.1:40881

2022-12-09 04:05 plan9-arm go@80f7484a os/exec.TestExtraFilesRace (log)

--- FAIL: TestExtraFilesRace (0.52s)
    exec_test.go:850: iteration 2, process B got:

        want:
        fd3: listener 127.0.0.1:55404

— watchflakes

[bcmills]

The above failures predate the fix (see #57632).