runtime/race: Tests pass with amd64 but fail with arm64 and ppc64le gohugoio/hugo

[anthonyfok]

While trying to add Travis CI’s new Multi-CPU feature—arm64 build—to Hugo (gohugoio/hugo#6467), I saw that go test -race ./... passes on AMD64, it fails Arm64: not that it detected a race condition, but certain tests are found to FAIL.

Debian’s arm64 porterbox amdahl.debian.org is down, but I was able to see similar failures on Debian’s ppc64le porterbox plummer.debian.org.

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

$ go version
go version go1.12.10 linux/arm64
go version go1.13.1 linux/arm64
go version devel +5b31021525 Fri Nov 1 07:59:09 2019 +0000 linux/arm64
go version go1.13.3 linux/ppc64le

Does this issue reproduce with the latest release?

Yes, it fails with Go 1.14 tip too, see https://travis-ci.org/gohugoio/hugo/jobs/605965543?utm_medium=notification&utm_source=github_status

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

go env Output on arm64 on Travis CI

$ go env
GO111MODULE="on"
GOARCH="arm64"
GOBIN=""
GOCACHE="/home/travis/.cache/go-build"
GOENV="/home/travis/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/travis/gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org"
GOROOT="/home/travis/.gimme/versions/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/travis/.gimme/versions/go/pkg/tool/linux_arm64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/travis/gopath/src/github.com/gohugoio/hugo/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build872332584=/tmp/go-build -gno-record-gcc-switches"

go env Output on ppc64le on Debian porterbox

(sid_ppc64el-dchroot)foka@plummer:~$ go env
GO111MODULE="on"
GOARCH="ppc64le"
GOBIN=""
GOCACHE="/home/foka/.cache/go-build"
GOENV="/home/foka/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="ppc64le"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/foka/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go-1.13"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go-1.13/pkg/tool/linux_ppc64le"
GCCGO="gccgo"
GOPPC64="power8"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build482247064=/tmp/go-build -gno-record-gcc-switches"

What did you do?

On arm64: Run mage -v check where gohugoio/hugo/magefile.go calls go test -race ./... in a Travis CI run.

On ppc64le:

export GO111MODULE=on
go get github.com/gohugoio/hugo
go test -race github.com/gohugoio/hugo/hugolib

What did you expect to see?

All tests pass, just like on amd64.

What did you see instead?

On arm64, from https://travis-ci.org/gohugoio/hugo/jobs/605965543#L515-L524:

--- FAIL: TestPageBundlerSiteRegular (0.01s)
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=true,canonify=false,path=NONE (41.57s)
        testing.go:870: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=true,canonify=true,path=NONE (44.51s)
        testing.go:870: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=false,canonify=true,path=NONE (47.44s)
        testing.go:870: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test

On ppc64le, tested on plummer.debian.org:

(sid_ppc64el-dchroot)foka@plummer:~$ go test -race -run TestPageBundlerSiteRegular github.com/gohugoio/hugo/hugolib
--- FAIL: TestPageBundlerSiteRegular (0.00s)
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=true,canonify=false,path=NONE (49.77s)
        testing.go:864: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=true,canonify=true,path=NONE (53.89s)
        testing.go:864: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=false,canonify=false,path=/hugo (58.00s)
        testing.go:864: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=false,canonify=true,path=NONE (62.14s)
        testing.go:864: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
    pagebundler_test.go:97: Build failed: "/work/base/b/my-bundle/index.md:1:1": timed out initializing value. This is most likely a circular loop in a shortcode
    --- FAIL: TestPageBundlerSiteRegular/ugly=false,canonify=true,path=/hugo (66.42s)
        testing.go:864: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
FAIL
FAIL	github.com/gohugoio/hugo/hugolib	66.555s
FAIL

[ceseo]

@laboger FYI

[FiloSottile]

It looks like you are hitting a timeout, and -race and arm64 might happen to be slow enough. Any reason to think this is a compiler or standard library issue? Does the failure go away if you increase the timeout?

[anthonyfok]

Thank you so much @FiloSottile. I think you are right, as some days later, I saw this apparent timeout when running the same test on my own amd64 laptop too when it was busy.

I will try to increase the timeout once I manage to find where it is set, and report back once I got the results on arm64 and ppc64le. Thanks again!

[anthonyfok]

I finally found an easy way to increase the timeout. Indeed, doubling the timeout from the default of 15000ms to 30000ms (by setting HUGO_TIMEOUT=30000) for arm64 on Travis CI solves the issue! (45000ms needed for plummer.debian.org). See gohugoio/hugo#6485 for details.

Thanks again for looking into this, and my apologies for the false alarm. I am glad that there is no cross-platform issue with Go’s race detector. :-) Closing this issue.