cmd/go: go1.11rc2 failed test: FAIL: TestScript/mod_get_commit

[ohir]

Building 1.11rc2 mod_get_commit fails

## environment
go version: devel +f2131f6e0c
go env:
GOARCH="amd64"
GOBIN="/certs/stage/cba/bin"
GOCACHE="/certs/stage/tst/go/.cache"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/certs/stage/tst/go"
GOPROXY=""
GORACE=""
GOROOT="/certs/stage/cba/go"
GOTMPDIR="/certs/stage/testbed/tmp"
GOTOOLDIR="/certs/stage/cba/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/certs/stage/testbed/tmp/go-build621289970=/tmp/go-build -gno-record-gcc-switches"

## go env did NOT print two important vars I have set:
GOROOT_BOOTSTRAP=/certs/stage/cba/go
GOROOT_FINAL=/certs/stage/cba/go

## make rc2
cd /local/go/repo
git checkout master
git pull
git checkout go1.11rc2
cd src
./all.bash
 ...
ok  	cmd/fix	6.453s
go test proxy starting
go test proxy running at GOPROXY=http://127.0.0.1:43443/mod
go proxy: no archive golang.org/x/text/language 14c0d48
go proxy: no archive golang.org/x/text/language 14c0d48
go proxy: no archive golang.org/x/text/language 14c0d48
go proxy: no archive w.1 v1.2.0
go proxy: no archive x.1 v1.0.0
go proxy: no archive z.1 v1.2.0
go proxy: no archive rsc.io v1.5.0
go proxy: no archive example.com/unused v0.0.0
go proxy: no archive example.com/unused v0.0.0
go proxy: no archive sub.1 v1.0.0
go proxy: no archive badsub.1 v1.0.0
go proxy: no archive versioned.1 v1.0.0
go proxy: no archive versioned.1 v1.1.0
go proxy: no archive example.com/split/subpkg v1.0.0
--- FAIL: TestScript (0.00s)
    --- FAIL: TestScript/mod_get_commit (0.57s)
        script_test.go:151: 
            # @commit should resolve
            # golang.org/x/text/language@commit should not resolve with -m,
            # because that's not a module path. (0.014s)
            # ... but it should work without -m.
            # because of -d, the compiler should not run (0.068s)
            # go get should skip build with no Go files in root (0.025s)
            # ... and go get should skip build with -m (0.026s)
            # dropping -d, we should see a build. (0.127s)
            # BUG: after the build, the package should not be stale, as 'go install' would
            # not do anything further. (0.173s)
            # install after get should not run the compiler again. (0.132s)
            > go install -x golang.org/x/text/language
            [stderr]
            WORK=$WORK/tmp/go-build955973672
            > ! stderr 'compile|cp|gccgo .*language\.a$'
            FAIL: testdata/script/mod_get_commit.txt:31: unexpected match for `compile|cp|gccgo .*language\.a$` found in stderr: compile
            
FAIL
FAIL	cmd/go	67.599s
...

[bradfitz]

/cc @rsc @bcmills

[ianlancetaylor]

Is this repeatable? Is that really the complete output?

I don't understand why it says that the regexp matches, when it clearly does not match the displayed output.

[ohir]

@ianlancetaylor
It is complete output for the failing test (but it is not complete output of all tests, of course.)
It is repeatable with go1.11rc2 and go1.10.3 (as bootstrap).
See attached log.

Peculiarities of my setup to consider:

• I do not use/export GOROOT.
• Compiling is done on tmpfs but not much restricted one (rw,relatime,mode=700)
• I am compiling with GOROOT_BOOTSTRAP==GOROOT_FINAL and both env vars are exported.
• All three tests now were with system provided gcc 4.8.5 (earlier report might had musl environment on). If gcc even matters.

goFailTest.log

[ohir]

Addenum: git version 2.13.7
This time I watched whole process. The offending test ate the console. I.e. up to
ok cmd/fix 2.507s line tests were printing regularly, then this FAIL and all below ok's were printed in one sweep at the test suite end. Also the tempdir has not been cleaned:

GOTMPDIR leftovers:
drwx------  8 test test6 180 08-24 12:04 .
drwx------ 10 test test6 340 08-24 12:06 ..
drwx------  2 test test6  40 08-24 12:02 go-build116293793
drwx------  2 test test6  40 08-24 12:02 go-build118789214
drwx------  2 test test6  40 08-24 12:03 go-build570765520
drwx------  2 test test6  40 08-24 12:03 go-build838072755
drwx------  2 test test6  40 08-24 12:03 go-build947615606
srwx------  1 test test6   0 08-24 12:01 go-nettest027823446
drwx------  2 test test6  40 08-24 12:00 go-tool-dist-446679995

note go-nettest027823446 socket

// @ianlancetaylor, @bradfitz

[ianlancetaylor]

The output behavior you describe is normal.

I just don't see how this error is possible.

At this point in the build the tools have been built and installed. What do you see if you run

go test -test.run=Script/mod_get_commit -test.v cmd/go

[ohir]

Log attached.

There is an interesting line:
go get golang.org/x/text/language@14c0d48: unexpected status (http://127.0.0.1:46135/mod/golang.org/x/text/language/@v/14c0d48.info): 500 Internal Server Error

likely as an effect of above line: go proxy: open /certs/stage/cba/go/src/cmd/go/testdata/mod/golang.org_x_text_language_14c0d48.txt: no such file or directory

Is there something like that?

find . -name "*14c0d48*"
./src/cmd/go/testdata/mod/golang.org_x_text_v0.0.0-20170915032832-14c0d48ead0c.txt

singleTestVerbose.log

[ianlancetaylor]

Thanks for the log. The 500 Internal Server Error is expected. Your log looks exactly as I expect, except for the incomprehensible failure at the end.

            > go install -x golang.org/x/text/language
            [stderr]
            WORK=$WORK/tmp/go-build664443131
            > ! stderr 'compile|cp|gccgo .*language\.a$'
            FAIL: testdata/script/mod_get_commit.txt:31: unexpected match for `compile|cp|gccgo .*language\.a$` found in stderr: compile

The failure is saying that given the text

WORK=$WORK/tmp/go-build664443131

the regexp compile|cp|gccgo .*language\.a$ matches that text, matching the string compile. But since compile does not appear in that single line of output, I have no idea what is going on.

[bcmills]

Is it possible that the elided $WORK prefix includes the substring compile?

[ohir]

@bcmills , @ianlancetaylor
> Is it possible that the elided $WORK prefix includes the substring compile?
Bingo!

Yes it was the culprit. There indeed on test machine was such word in path's part.
(I must not show real paths due to our security policy). Thanks for resolving this mistery.

It was in GOTMPDIR path. Pointing it to path without mentioned word makes test pass.

[ianlancetaylor]

@bcmills Argh, thanks for figuring that out.

[gopherbot]

Change https://golang.org/cl/131398 mentions this issue: cmd/go: don't let script grep commands match $WORK

[gopherbot]

Change https://golang.org/cl/131399 mentions this issue: [release-branch.go1.11] cmd/go: don't let script grep commands match $WORK