os/exec: TestExtraFiles is flaky on 32-bit linux builders #25628

ALTree · 2018-05-29T18:22:19Z

I've seen several of these:

--- FAIL: TestExtraFiles (0.10s)
	exec_test.go:607: Run: exit status 1; stdout "leaked parent file. fd = 66; want 65\n", stderr ""
FAIL
FAIL	os/exec	0.687s

on the linux-386-sid builder in the past weeks. Here's one:

https://build.golang.org/log/b95e0220b4130af6c1bcfed59ec934568717d0ef

The text was updated successfully, but these errors were encountered:

ianlancetaylor · 2018-05-31T22:13:05Z

That is odd. The errors show relatively large descriptor numbers. It implies that something in the system is opening a large descriptor before running make.bash.

bcmills · 2018-06-01T20:50:38Z

There is another recurring failure mode in os/exec on linux-386-sid that produces broken pipe instead. Any idea whether they're related?

An example failure (https://build.golang.org/log/cef4b584d2ccb30621e2965de0517f6077aa2f92):

testing: can't write /tmp/go-build619681385/b056/testlog.txt: write /tmp/go-build619681385/b056/testlog.txt: broken pipe
FAIL	os/exec	0.697s

ianlancetaylor · 2018-06-01T21:31:10Z

Yes, they could be related. The os/exec package tries to guess which descriptor is being used for testlog.txt; if it guesses wrong, because of an unexpectedly open descriptor, that could cause the broken pipe error.

ianlancetaylor · 2018-06-27T18:25:08Z

ianlancetaylor · 2018-06-27T18:28:15Z

Since this doesn't seem to be happening anywhere else, this is most likely a problem specific to the linux-386-sid builder. Something on that system is causing the os/exec tests to run with an unexpectedly open file descriptor.

@bradfitz Is there anything unusual about the linux-386-sid builder?

bradfitz · 2018-06-27T18:38:48Z

The 386-sid builder is an amd64 Docker container (like all our linux-386-*) builders with the "debian:sid" base layer (https://github.com/golang/build/blob/master/env/linux-x86-sid/Dockerfile). We occasionally re-build it to reflect the ever-changing Debian sid.

Last updates:

April 11, 2017
Nov 2, 2017
May 8, 2018 (current)

ALTree · 2018-07-07T10:55:38Z

This was reported to also happen on a linux_386 Virtualbox machine with an updated Ubuntu Mate 18.04 LTS and boostrap Go version 1.4.3 (Issue #26261).

mikesmitty · 2018-08-24T02:50:42Z

Ran into this issue with 1.11rc2 on Fedora 27 i386 as well:

--- FAIL: TestExtraFiles (0.07s)
    exec_test.go:607: Run: exit status 1; stdout "leaked parent file. fd = 66; want 65\n", stderr ""
FAIL
FAIL	os/exec	1.074s

bobvanderlinden · 2018-09-15T16:22:25Z

This happens on NixOS as well. There it seems to be happening reliably as I can reproduce it on my laptop again and again. The NixOS build server also reproduces the error for every build.

This happens on go 1.11.

For reference: https://hydra.nixos.org/build/80999166/nixlog/12

This seems to only happen on i686 on go 1.11. It also happens on Debian. For more information: golang/go#25628

This seems to only happen on i686 on go 1.11. It also happens on Debian. For more information: golang/go#25628 (cherry picked from commit 0bf6b44)

ianlancetaylor · 2018-12-20T02:16:03Z

@bradfitz The test will try to run lsof when it finds a leaked FD. That isn't happening on linux-386-sid. Could we get the lsof package installed on that system?

bradfitz · 2018-12-20T03:10:18Z

@ianlancetaylor, I filed #29347 for somebody to do that.

bcmills · 2019-06-14T02:21:53Z

Still flaky, but no lsof yet.
https://build.golang.org/log/337a9a3bfffb327f66750c82f0ab47b9f796576b

bcmills · 2019-07-03T14:49:54Z

https://build.golang.org/log/300479013a9843f238f5e1af1b7906c6b63b5be2

rsc · 2020-03-24T13:38:24Z

I am a bit confused about this code:

    for fd := uintptr(3); fd <= 100; fd++ {
            if poll.IsPollDescriptor(fd) {
                    continue
            }
            // We have no good portable way to check whether an FD is open.
            // We use NewFile to create a *os.File, which lets us
            // know whether it is open, but then we have to cope with
            // the finalizer on the *os.File.
            f := os.NewFile(fd, "")
            if _, err := f.Stat(); err != nil {
                    // Close the file to clear the finalizer.
                    // We expect the Close to fail.
                    f.Close()
            } else {
                    fmt.Printf("fd %d open at test start\n", fd)
                    haveUnexpectedFDs = true
                    // Use a global variable to avoid running
                    // the finalizer, which would close the FD.
                    unfinalizedFiles = append(unfinalizedFiles, f)
            }
    }

This is in a func init. I don't understand what is starting the network at all. Why is poll.IsPollDescriptor required?

If it is required, then it looks like this code is racing against netpollinit, in which case (1) IsPollDescriptor should be using atomics, if only to prevent the compiler from optimizing away the repeated loads, and (2) it needs to be double-checked after we detect an issue. The epfd might be -1 at the start of the loop, but its creation is racing with our os.NewFile, and epfd wins: epfd gets the fd we want, and we get fd+1. In that case, we should fd++; continue instead of failing.

ianlancetaylor · 2020-03-24T20:10:26Z

The network is now started whenever you create a timer, which could conceivably happen in an init function somewhere in the test. Likely nothing is starting the network here, but calling IsPollDescriptor is cheap. There shouldn't be a race unless some init function starts a goroutine.

For this issue, I don't think it matters. The point of that code was to report whether any descriptors are open when the test starts. The logs show that they aren't. If there were somehow a race on IsPollDescriptor, it would show that there were descriptors open (the poll descriptors). We aren't seeing that.

ianlancetaylor · 2020-03-24T20:14:31Z

I sent https://golang.org/cl/225278 for the os.Readlink suggestion.

gopherbot · 2020-03-24T20:14:32Z

Change https://golang.org/cl/225278 mentions this issue: os/exec: for TestExtraFiles failure, print readlink of unexpeced fd

For #25628 Change-Id: If1dce7ba9310e1418e67b9954c989471b775a28e Reviewed-on: https://go-review.googlesource.com/c/go/+/225278 Run-TryBot: Ian Lance Taylor <iant@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org>

bcmills · 2020-03-27T02:33:31Z

We have a hit with the new readlink logging, but it doesn't seem particularly illuminating:

2020-03-26T16:12:18-d1ecfcc/linux-386-clang

--- FAIL: TestExtraFiles (1.31s)
    exec_test.go:686: Run: exit status 1
        --- stdout:
        leaked parent file. fd = 66; want 65
        readlink("/proc/self/fd/65") = "", readlink /proc/self/fd/65: no such file or directory

ianlancetaylor · 2020-03-27T17:10:44Z

That's just weird. The code looks fine to me. Seems like this could only open if some other goroutine briefly opens and closes a descriptor. But I can't think of what would do that. Or why it would be specific to these builders.

I sent CL 225799 to run the test under strace. Perhaps that will show us something.

gopherbot · 2020-03-27T17:10:48Z

Change https://golang.org/cl/225799 mentions this issue: os/exec: add temporary debugging code for #25628

On linux-386 builders run the TestExtraFiles subprocess under strace, in hopes of finding out where the unexpected descriptor is coming from. For #25628 Change-Id: I9a62d6a5192a076525a616ccc71de74bbe7ebd58 Reviewed-on: https://go-review.googlesource.com/c/go/+/225799 Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com>

bcmills · 2020-04-07T16:10:38Z

The new debugging code seems to be deadlocking or otherwise timing out instead of generating output.

2020-04-04T01:01:04-fff7509/linux-386-sid
2020-04-03T17:08:32-3103495/linux-386-sid
2020-03-31T04:31:04-d98023e/linux-386-clang

gopherbot · 2020-04-07T23:41:01Z

Change https://golang.org/cl/227517 mentions this issue: os/exec: use subprocess deadline in TestExtraFiles

Try to get some output even if the subprocess hangs. For #25628 Change-Id: I4cc0a8f2c52b03a322b8fd0a620cba37b06ff10a Reviewed-on: https://go-review.googlesource.com/c/go/+/227517 Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com>

bcmills · 2020-04-09T15:06:54Z

Looks like we need a longer grace period on the deadline https://build.golang.org/log/8cdf7d284333d1fd9307916177b4ea66f1d898f0):

panic: test timed out after 3m0s
…
goroutine 38 [runnable]:
strings.Index(0x3c43c6b4, 0xb86e8d0, 0x8343ff8, 0x1, 0x48)
	/workdir/go/src/strings/strings.go:1019 +0x422
strings.genSplit(0x3c43c6b4, 0xb86e8d0, 0x8343ff8, 0x1, 0x0, 0x2e9bee, 0x2, 0x12, 0x0)
	/workdir/go/src/strings/strings.go:251 +0xc2
strings.Split(...)
	/workdir/go/src/strings/strings.go:299
testing.(*common).decorate(0xa52ef00, 0x3a800000, 0xd4aaf84, 0x4, 0xa42ed80, 0xf7cb3750)
	/workdir/go/src/testing/testing.go:493 +0x1e7
testing.(*common).logDepth(0xa52ef00, 0x3a800000, 0xd4aaf84, 0x3)
	/workdir/go/src/testing/testing.go:693 +0x1c9
testing.(*common).log(...)
	/workdir/go/src/testing/testing.go:669
testing.(*common).Fatalf(0xa52ef00, 0x8350ec8, 0x24, 0xa53bf54, 0x3, 0x3)
	/workdir/go/src/testing/testing.go:730 +0x65
os/exec_test.TestExtraFiles(0xa52ef00)
	/workdir/go/src/os/exec/exec_test.go:704 +0x93a
testing.tRunner(0xa52ef00, 0x8360064)
	/workdir/go/src/testing/testing.go:1022 +0xb4
created by testing.(*T).Run
	/workdir/go/src/testing/testing.go:1073 +0x2ad

I'll send a CL.

gopherbot · 2020-04-09T15:14:04Z

Change https://golang.org/cl/227765 mentions this issue: os/exec: extend grace period in TestExtraFiles to 10% of overall deadline

…line Updates #25628 Change-Id: I938a7646521b34779a3a57833e7ce9d508b58faf Reviewed-on: https://go-review.googlesource.com/c/go/+/227765 Run-TryBot: Bryan C. Mills <bcmills@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Ian Lance Taylor <iant@golang.org>

bcmills · 2020-04-13T14:53:01Z

It worked! We have some strace outputs:
https://build.golang.org/log/76649c297be946b148e1c8b424637ad8d8cf177b
https://build.golang.org/log/5d21f8205e46d20f4ad3afb3bd5ed5a6ebd018df

ianlancetaylor · 2020-04-13T18:44:30Z

Excellent. In both cases the extraneous file descriptor was due to opening /sys/devices/system/cpu/online. It seems to be associated with calls to the set_robust_list system call, which is called among other places by a newly started C thread. I think the most likely sequence of events here is a libc starting a new thread when a cgo-using program calls pthread_create via _cgo_thread_start. _cgo_thread_start calls the C malloc function. When malloc needs to create a new arena for the first time, it calls __get_nprocs. __get_nprocs opens /sys/devices/system/cpu/online to see how many processors the system has.

But I do not know why this only happens on 386 systems. I may be missing a step.

ianlancetaylor · 2020-04-13T22:03:25Z

I filed https://sourceware.org/bugzilla/show_bug.cgi?id=25817 for glibc to stop doing this.

gopherbot · 2020-04-13T22:06:36Z

Change https://golang.org/cl/228099 mentions this issue: os/exec: create extra threads when starting a subprocess

TestExtraFiles seems to be flaky on GNU/Linux systems when using cgo because creating a new thread will call malloc which can create a new arena which can open a file to see how many processors there are. Try to avoid the flake by creating several new threads at process startup time. For #25628 Change-Id: Ie781acdbba475d993c39782fe172cf7f29a05b24 Reviewed-on: https://go-review.googlesource.com/c/go/+/228099 Reviewed-by: Bryan C. Mills <bcmills@google.com>

bcmills · 2020-04-16T15:19:54Z

Hmm, the extra threads seem to have made it flaky on 64-bit builders:

2020-04-16T03:19:50-ab3bd2c/linux-arm64-packet
2020-04-15T20:12:13-aa3413c/linux-mips64le-mengzhuo

That's... unexpected. Maybe we should skip this test on cgo-enabled configurations?

ianlancetaylor · 2020-04-17T00:52:56Z

I think I must have missed something.

I think you're right that we should run this test without cgo. I think that just skipping if cgo is enabled would effectively mean that we never run the test. But we should be able to make this work.

gopherbot · 2020-04-17T01:20:50Z

Change https://golang.org/cl/228639 mentions this issue: os/exec: build TestExtraFiles subprocess without cgo

erifan · 2020-04-20T07:11:17Z

Hi, does TestExtraFiles now require 'lsof' to be installed in the test environment? Because I still see this test fail on our linux/amd64 and linux/arm64 machines.

Repo: 4eaf855
Arch: linux/amd64

00:52:34 --- FAIL: TestExtraFiles (0.14s)
00:52:34     exec_test.go:708: Run: exit status 1
00:52:34         --- stdout:
00:52:34         leaked parent file. fd = 67; want 65
00:52:34         readlink("/proc/self/fd/65") = "", readlink /proc/self/fd/65: no such file or directory
00:52:34         --- stderr:
00:52:34         lsof -p 37167 failed: exec: "lsof": executable file not found in $PATH
00:52:34 FAIL
00:52:34 FAIL	os/exec	1.244s

Arch: linux/arm64

20:59:22 --- FAIL: TestExtraFiles (0.19s)
20:59:22     exec_test.go:708: Run: exit status 1
20:59:22         --- stdout:
20:59:22         leaked parent file. fd = 5; want 4
20:59:22         readlink("/proc/self/fd/4") = "/sys/devices/system/cpu/online", <nil>
20:59:22         --- stderr:
20:59:22         lsof -p 19941 failed: exec: "lsof": executable file not found in $PATH
20:59:22 FAIL
20:59:22 FAIL	os/exec	1.095s

ianlancetaylor · 2020-04-21T00:04:56Z

TestExtraFiles does not require lsof to be installed. It invokes lsof if it fails, in an attempt to find out why it failed. But if it does not fail, it does not invoke lsof.

Fortunately it looks like your failure appeared before https://golang.org/cl/228639 was committed, as I think that CL should fix the test.

ALTree added Testing An issue that has been verified to require only test changes, not just a test failure. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels May 29, 2018

bcmills added the OS-Linux label May 29, 2018

ianlancetaylor added this to the Go1.11 milestone May 31, 2018

ALTree changed the title ~~os/exec: TestExtraFiles is flaky on linux-386-sid bulder~~ os/exec: TestExtraFiles is flaky on linux-386-sid builder Jun 2, 2018

ianlancetaylor modified the milestones: Go1.11, Go1.12 Jun 27, 2018

ALTree mentioned this issue Jul 7, 2018

all.bash: fails in a linux_386 Virtualbox machine #26261

Closed

bobvanderlinden mentioned this issue Sep 15, 2018

Failing tests for go-1.11 on i686-linux NixOS/nixpkgs#46705

Closed

bobvanderlinden added a commit to bobvanderlinden/nixpkgs that referenced this issue Sep 15, 2018

go: skip flaky os/exec TestExtraFiles

0bf6b44

This seems to only happen on i686 on go 1.11. It also happens on Debian. For more information: golang/go#25628

bobvanderlinden mentioned this issue Sep 15, 2018

go: skip flaky os/exec TestExtraFiles NixOS/nixpkgs#46706

Merged

9 tasks

Mic92 pushed a commit to NixOS/nixpkgs that referenced this issue Sep 16, 2018

go: skip flaky os/exec TestExtraFiles

9179259

This seems to only happen on i686 on go 1.11. It also happens on Debian. For more information: golang/go#25628 (cherry picked from commit 0bf6b44)

ianlancetaylor modified the milestones: Go1.12, Go1.13 Dec 20, 2018

bradfitz mentioned this issue Dec 20, 2018

x/build/env: make sure "lsof" is available on linux-386-sid #29347

Closed

andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019

gopherbot closed this as completed in 98c6b98 Apr 18, 2020

bcmills mentioned this issue Nov 9, 2020

os/exec: TestExtraFiles failures on illumos-amd64 builder #42463

Closed

ianlancetaylor mentioned this issue Nov 11, 2020

os/exec: occasional "leaked parent file" on illumos/amd64 #42431

Closed

golang locked and limited conversation to collaborators Apr 21, 2021

gopherbot added the FrozenDueToAge label Apr 21, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

os/exec: TestExtraFiles is flaky on 32-bit linux builders #25628

os/exec: TestExtraFiles is flaky on 32-bit linux builders #25628

ALTree commented May 29, 2018

ianlancetaylor commented May 31, 2018

bcmills commented Jun 1, 2018

ianlancetaylor commented Jun 1, 2018

ianlancetaylor commented Jun 27, 2018

ianlancetaylor commented Jun 27, 2018

bradfitz commented Jun 27, 2018

ALTree commented Jul 7, 2018

mikesmitty commented Aug 24, 2018

bobvanderlinden commented Sep 15, 2018 •

edited

ianlancetaylor commented Dec 20, 2018

bradfitz commented Dec 20, 2018

bcmills commented Jun 14, 2019

bcmills commented Jul 3, 2019

rsc commented Mar 24, 2020

ianlancetaylor commented Mar 24, 2020

ianlancetaylor commented Mar 24, 2020

gopherbot commented Mar 24, 2020

bcmills commented Mar 27, 2020 •

edited

ianlancetaylor commented Mar 27, 2020

gopherbot commented Mar 27, 2020

bcmills commented Apr 7, 2020

gopherbot commented Apr 7, 2020

bcmills commented Apr 9, 2020

gopherbot commented Apr 9, 2020

bcmills commented Apr 13, 2020

ianlancetaylor commented Apr 13, 2020

ianlancetaylor commented Apr 13, 2020

gopherbot commented Apr 13, 2020

bcmills commented Apr 16, 2020

ianlancetaylor commented Apr 17, 2020

gopherbot commented Apr 17, 2020

erifan commented Apr 20, 2020

ianlancetaylor commented Apr 21, 2020

os/exec: TestExtraFiles is flaky on 32-bit linux builders #25628

os/exec: TestExtraFiles is flaky on 32-bit linux builders #25628

Comments

ALTree commented May 29, 2018

ianlancetaylor commented May 31, 2018

bcmills commented Jun 1, 2018

ianlancetaylor commented Jun 1, 2018

ianlancetaylor commented Jun 27, 2018

ianlancetaylor commented Jun 27, 2018

bradfitz commented Jun 27, 2018

ALTree commented Jul 7, 2018

mikesmitty commented Aug 24, 2018

bobvanderlinden commented Sep 15, 2018 • edited

ianlancetaylor commented Dec 20, 2018

bradfitz commented Dec 20, 2018

bcmills commented Jun 14, 2019

bcmills commented Jul 3, 2019

rsc commented Mar 24, 2020

ianlancetaylor commented Mar 24, 2020

ianlancetaylor commented Mar 24, 2020

gopherbot commented Mar 24, 2020

bcmills commented Mar 27, 2020 • edited

ianlancetaylor commented Mar 27, 2020

gopherbot commented Mar 27, 2020

bcmills commented Apr 7, 2020

gopherbot commented Apr 7, 2020

bcmills commented Apr 9, 2020

gopherbot commented Apr 9, 2020

bcmills commented Apr 13, 2020

ianlancetaylor commented Apr 13, 2020

ianlancetaylor commented Apr 13, 2020

gopherbot commented Apr 13, 2020

bcmills commented Apr 16, 2020

ianlancetaylor commented Apr 17, 2020

gopherbot commented Apr 17, 2020

erifan commented Apr 20, 2020

ianlancetaylor commented Apr 21, 2020

bobvanderlinden commented Sep 15, 2018 •

edited

bcmills commented Mar 27, 2020 •

edited