x/build: freebsd-arm-paulzhol builder is failing cmd/link TestDWARF

[paulzhol]

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

ok  	cmd/internal/src	0.034s
ok  	cmd/internal/test2json	1.729s
--- FAIL: TestDWARF (4.86s)
    dwarf_test.go:41: cmd/link is stale - run go install cmd/link
FAIL
FAIL	cmd/link	56.431s
FAIL
go tool dist: Failed: exit status 1

I've captured the stdout/stderr output from the buildlet to look at the env. variables as I understand it was related to clearing GOROOT_FINAL in similar issues.

2020/08/28 11:21:06 [0x314ba580] Running /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go with args ["/tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go" "tool" "dist" "test" "--no-rebuild" "--banner=XXXBANNERXXX:" "go_test:cmd/internal/obj/riscv" "go_test:cmd/internal/obj/x86" "go_test:cmd/internal/objabi"] and env ["BLOCKSIZE=K" "MAIL=/var/mail/paulzhol" "PATH=/tmp/workdir-host-freebsd-arm-paulzhol/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin" "GO_TEST_TIMEOUT_SCALE=30" "CGO_ENABLED=1" "GOARM=7" "XDG_CACHE_HOME=/tmp/cache" "USER=paulzhol" "HOME=/home/paulzhol" "PWD=/" "RC_PID=21" "WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4" "GO_BUILDER_NAME=freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4" "GOARM=7" "CGO_ENABLED=1" "GOROOT=/tmp/workdir-host-freebsd-arm-paulzhol/go" "GOPATH=/tmp/workdir-host-freebsd-arm-paulzhol/gopath" "GOPROXY=http://10.240.0.3:30157" "GOPROXY=off" "TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp" "GOCACHE=/tmp/workdir-host-freebsd-arm-paulzhol/gocache"] in dir /tmp/workdir-host-freebsd-arm-paulzhol
2020/08/28 11:22:09 [0x314ba580] Run = ok, after 1m3.510284157s

2020/08/28 11:22:09 [0x314bb1e0] Running /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go with args ["/tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go" "tool" "dist" "test" "--no-rebuild" "--banner=XXXBANNERXXX:" "go_test:cmd/internal/src" "go_test:cmd/internal/test2json" "go_test:cmd/link"] and env ["BLOCKSIZE=K" "MAIL=/var/mail/paulzhol" "PATH=/tmp/workdir-host-freebsd-arm-paulzhol/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin" "GO_TEST_TIMEOUT_SCALE=30" "CGO_ENABLED=1" "GOARM=7" "XDG_CACHE_HOME=/tmp/cache" "USER=paulzhol" "HOME=/home/paulzhol" "PWD=/" "RC_PID=21" "WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4" "GO_BUILDER_NAME=freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4" "GOARM=7" "CGO_ENABLED=1" "GOROOT=/tmp/workdir-host-freebsd-arm-paulzhol/go" "GOPATH=/tmp/workdir-host-freebsd-arm-paulzhol/gopath" "GOPROXY=http://10.240.0.3:30157" "GOPROXY=off" "TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp" "GOCACHE=/tmp/workdir-host-freebsd-arm-paulzhol/gocache"] in dir /tmp/workdir-host-freebsd-arm-paulzhol
2020/08/28 11:23:49 [0x314bb1e0] Run = exit status 1, after 1m39.66510577s

2020/08/28 11:23:49 [0x3148cdc0] Running /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go with args ["/tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go" "tool" "dist" "test" "--no-rebuild" "--banner=XXXBANNERXXX:" "go_test:cmd/link/internal/benchmark" "go_test:cmd/link/internal/ld" "go_test:cmd/link/internal/loader"] and env ["BLOCKSIZE=K" "MAIL=/var/mail/paulzhol" "PATH=/tmp/workdir-host-freebsd-arm-paulzhol/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin" "GO_TEST_TIMEOUT_SCALE=30" "CGO_ENABLED=1" "GOARM=7" "XDG_CACHE_HOME=/tmp/cache" "USER=paulzhol" "HOME=/home/paulzhol" "PWD=/" "RC_PID=21" "WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4" "GO_BUILDER_NAME=freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4" "GOARM=7" "CGO_ENABLED=1" "GOROOT=/tmp/workdir-host-freebsd-arm-paulzhol/go" "GOPATH=/tmp/workdir-host-freebsd-arm-paulzhol/gopath" "GOPROXY=http://10.240.0.3:30157" "GOPROXY=off" "TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp" "GOCACHE=/tmp/workdir-host-freebsd-arm-paulzhol/gocache"] in dir /tmp/workdir-host-freebsd-arm-paulzhol
2020/08/28 11:23:50 Halting in 1 second.

Maybe this is a dup of #33598 but on FreeBSD-arm.

[cagedmantis]

/cc @andybons @dmitshur @toothrot

[bcmills]

I refactored that test in CL 236819 for #39385.

I notice that there are two occurrences of GOROOT_BOOTSTRAP in the environment in the linked log — could that be causing the discrepancy? (See also #31567.)

[paulzhol]

@bcmills The first one is wrong (GOROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4) and it is the default set by the buildlets main():

https://github.com/golang/build/blob/1f82dd332eb91abb9335fc2abc4d8039f7ac7ba5/cmd/buildlet/buildlet.go#L255-L264

var inheritedGorootBootstrap string

func initGorootBootstrap() {
	// Remember any GOROOT_BOOTSTRAP to use as a backup in handleExec
	// if $WORKDIR/go1.4 ends up not existing.
	inheritedGorootBootstrap = os.Getenv("GOROOT_BOOTSTRAP")

	// Default if not otherwise configured in dashboard/builders.go:
	os.Setenv("GOROOT_BOOTSTRAP", filepath.Join(*workDir, "go1.4"))
}

the second GOROOT_BOOTSTRAP is coming from the (coordinator?):

https://github.com/golang/build/blob/1e76199ae864f03a22993c156ef26ecc4679e7f4/dashboard/builders.go#L844-L857

// Env returns the environment variables this builder should run with.
func (c *BuildConfig) Env() []string {
	env := []string{"GO_BUILDER_NAME=" + c.Name}
	if c.FlakyNet {
		env = append(env, "GO_BUILDER_FLAKY_NET=1")
	}
	if c.IsLongTest() {
		// Set a private hook in cmd/dist to run main Go repository tests
		// without the default -short flag. See golang.org/issue/12508.
		env = append(env, "GO_TEST_SHORT=0")
	}
	env = append(env, c.HostConfig().env...)
	return append(env, c.env...)
}

from:
https://github.com/golang/build/blob/18a463e644997ff721e2f319f030b5fd63d4739d/dashboard/builders.go#L347

	"host-freebsd-arm-paulzhol": &HostConfig{
		IsReverse:   true,
		ExpectNum:   1,
		Notes:       "Cubiboard2 1Gb RAM dual-core Cortex-A7 (Allwinner A20), FreeBSD 11.1-RELEASE",
		env:         []string{"GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4"},
		OwnerGithub: "paulzhol",
	},

but eventually this is just passed to an os/exec.Cmd struct in the buildlet exec handler, where

// If Env contains duplicate environment keys, only the last
// value in the slice for each duplicate key is used.
// As a special case on Windows, SYSTEMROOT is always added if
// missing and not explicitly set to the empty string.
Env []string

I randomly sampled an active build, and only the correct (last) value is set:

1527  -  S     0:56.71 /var/tmp/workdir-host-freebsd-arm-paulzhol/go/pkg/tool/freebsd_arm/go_bootstrap install -gcflags=all= -ldflags=all= std cmd

[paulzhol@arm-virt-12 ~]$ procstat -e 1527
  PID COMM             ENVIRONMENT
 1527 go_bootstrap     CGO_ENABLED=1 RC_PID=21 GO_BUILDER_NAME=freebsd-arm-paulzhol GO_TEST_TIMEOUT_SCALE=30 USER=paulzhol GOENV=off PWD=/var/tmp/workdir-host-freebsd-arm-paulzhol/go/src HOME=/home/paulzhol GOROOT=/var/tmp/workdir-host-freebsd-arm-paulzhol/go TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp MAIL=/var/mail/paulzhol SHLVL=1 WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol BLOCKSIZE=K XDG_CACHE_HOME=/tmp/cache PATH=/var/tmp/workdir-host-freebsd-arm-paulzhol/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin GOCACHE=/var/tmp/workdir-host-freebsd-arm-paulzhol/go/pkg/obj/go-build GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4 GOARM=7 _=./cmd/dist/dist TERM=dumb GO386=387 GOARCH=arm GOHOSTARCH=arm GOHOSTOS=freebsd GOOS=freebsd GOMIPS=hardfloat GOMIPS64=hardfloat GOPPC64=power8 GOROOT_FINAL=/var/tmp/workdir-host-freebsd-arm-paulzhol/go LANG=C LANGUAGE=en_US.UTF8 GOPATH=/var/tmp/workdir-host-freebsd-arm-paulzhol/go/pkg/obj/gopath GOBIN= CC=clang
[paulzhol@arm-virt-12 ~]$ ls -l /var/tmp/workdir-host-freebsd-arm-paulzhol/go

Looking at the PATH above, and #31567 (comment) I don't have the bootstrap go1.4 set, or is there any other go installation present.

The other difference I can think of, is my builder has the entire filesystem mounted read-only, so https://golang.org/cl/223746 is needed to ignore failing writes. Although GOROOT=/var/tmp/workdir-host-freebsd-arm-paulzhol/go set above is writable anyway.

[aclements]

There was some discussion in #43197 about this test before I closed that as a dup of this issue.

cc @golang/osp-team @cherrymui @jeremyfaller @thanm

[paulzhol]

I have a suspicion as to why this is happening, but I'm not sure how to prove it: I think there is at least one other parallel build in progress while the TestDWARF is running. This lingering build is maybe caused by GO_TEST_TIMEOUT_SCALE=10 and the builder being super-slow as it is. The lingering build has different compiler flags set, which trigger the cmd/link is stale failure in TestDWARF.
Also I couldn't trigger the cmd/link is stale by running just the TestDWARF test right after a make.bash.

In the SlowBots run for https://golang.org/cl/276892 (log)

captured STDOUT

2020/12/15 21:52:36 [0x314b2fd0] Running /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go with args ["/tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go" "tool" "dist" "test" "--no-rebuild" "--banner=XXXBANNERXXX:" "go_test:cmd/internal/src" "go_test:cmd/internal/sys" "go_test:cmd/internal/test2json"] and env ["BLOCKSIZE=K" "MAIL=/var/mail/paulzhol" "PATH=/tmp/workdir-host-freebsd-arm-paulzhol/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin" "GO_TEST_TIMEOUT_SCALE=10" "XDG_CACHE_HOME=/tmp/cache" "USER=paulzhol" "HOME=/home/paulzhol" "PWD=/" "RC_PID=21" "WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4" "GO_BUILDER_NAME=freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4" "GOARM=7" "CGO_ENABLED=1" "GOROOT=/tmp/workdir-host-freebsd-arm-paulzhol/go" "GOPATH=/tmp/workdir
-host-freebsd-arm-paulzhol/gopath" "GOPROXY=http://10.240.0.3:30157" "GOPROXY=off" "TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp" "GOCACHE=/tmp/workdir-host-freebsd-arm-paulzhol/gocache"] in dir /tmp/workdir-host-freebsd-arm-paulzhol

2020/12/15 21:53:05 [0x314b2fd0] Run = ok, after 28.637322489s
2020/12/15 21:53:05 [0x3145cb00] Running /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go with args ["/tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go" "tool" "dist" "test" "--no-rebuild" "--banner=XXXBANNERXXX:" "go_test:cmd/link" "go_test:cmd/link/internal/benchmark" "go_test:cmd/link/internal/ld"] and env ["BLOCKSIZE=K" "MAIL=/var/mail/paulzhol" "PATH=/tmp/workdir-host-freebsd-arm-paulzhol/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin" "GO_TEST_TIMEOUT_SCALE=10" "XDG_CACHE_HOME=/tmp/cache" "USER=paulzhol" "HOME=/home/paulzhol" "PWD=/" "RC_PID=21" "WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4" "GO_BUILDER_NAME=freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/usr/home/paulzhol/go1.4" "GOARM=7" "CGO_ENABLED=1" "GOROOT=/tmp/workdir-host-freebsd-arm-paulzhol/go" "GOPATH=/tmp/workdir-host-freebsd-arm-paulzhol/gopath" "GOPROXY=http://10.240.0.3:30157" "GOPROXY=off" "TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp" "GOCACHE=/tmp/workdir-host-freebsd-arm-paulzhol/gocache"] in dir /tmp/workdir-host-freebsd-arm-paulzhol

2020/12/15 21:57:18 [0x3145cb00] Run = exit status 1, after 4m12.7549214s                                                     
2020/12/15 21:57:18 [0x3145cfd0] Running /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go with args ["/tmp/workdir-host-freebs$
-arm-paulzhol/go/bin/go" "tool" "dist" "test" "--no-rebuild" "--banner=XXXBANNERXXX:" "go_test:cmd/link/internal/loader" "go_t$
st:cmd/nm" "go_test:cmd/objdump"] and env ["BLOCKSIZE=K" "MAIL=/var/mail/paulzhol" "PATH=/tmp/workdir-host-freebsd-arm-paulzho$
/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/home/paulzhol/bin" "GO_TEST_TIMEOUT_SCALE=10" "XDG_CACHE$
HOME=/tmp/cache" "USER=paulzhol" "HOME=/home/paulzhol" "PWD=/" "RC_PID=21" "WORKDIR=/tmp/workdir-host-freebsd-arm-paulzhol" "G$
ROOT_BOOTSTRAP=/tmp/workdir-host-freebsd-arm-paulzhol/go1.4" "GO_BUILDER_NAME=freebsd-arm-paulzhol" "GOROOT_BOOTSTRAP=/usr/hom$
/paulzhol/go1.4" "GOARM=7" "CGO_ENABLED=1" "GOROOT=/tmp/workdir-host-freebsd-arm-paulzhol/go" "GOPATH=/tmp/workdir-host-freebs$
-arm-paulzhol/gopath" "GOPROXY=http://10.240.0.3:30157" "GOPROXY=off" "TMPDIR=/tmp/workdir-host-freebsd-arm-paulzhol/tmp" "GOC$
CHE=/tmp/workdir-host-freebsd-arm-paulzhol/gocache"] in dir /tmp/workdir-host-freebsd-arm-paulzhol

I saw a build running with -ldflags=-linkmode=internal :

paulzhol@nanobsd-virt:~ % procstat -c 9590                                                                                     
  PID COMM             ARGS                                                                                                    
 9590 go               /tmp/workdir-host-freebsd-arm-paulzhol/go/bin/go build -ldflags=-linkmode=internal -o /tmp/workdir-host-
freebsd-arm-paulzhol/tmp/TestMacOSVersion909022279/main /tmp/workdir-host-freebsd-arm-paulzhol/tmp/TestMacOSVersion909022279/ma
in.go

Could it have forced a rebuild of the toolchain (triggering the cmd/link is stale)?

[aclements]

Bump. @cherrymui @jeremyfaller @thanm, do any of you have time to look at this? It would be good for this builder to be green before the release. At least in principle the builder is more accessible now, though I waited 10 minutes for it before giving up.