cmd/link: panic: sym already present in installSym on FreeBSD/amd64

[SamWhited]

This happened on the same runner as #42658, though I don't see what that could have to do with anything unless I'm just very unlucky and these are hardware issues or something. Like that one, I can't reproduce it after the first time.

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

$ go version
go version go1.15.5 freebsd/amd64

Does this issue reproduce with the latest release?

Unsure, it only happened once and I can't reproduce it again.

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/build/.cache/go-build"
GOENV="/home/build/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="freebsd"
GOINSECURE=""
GOMODCACHE="/home/build/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="freebsd"
GOPATH="/home/build/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/freebsd_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
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 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build974778974=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I ran go test -v -cover ./... against mellium.im/xmpp in CI.

Build is here: https://builds.sr.ht/~samwhited/job/349374

What did you see instead?

# mellium.im/xmpp/x509.test
panic: sym already present in installSym

goroutine 1 [running]:
cmd/link/internal/loader.(*Loader).installSym(...)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2447
cmd/link/internal/loader.(*Loader).addNewSym(0xc000065c00, 0x5b8f, 0x0, 0x0, 0x0, 0xc0000b99e0, 0xffffffffffffff33, 0x0)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2465 +0x245
cmd/link/internal/loader.loadObjSyms(0xc000065c00, 0xc00000c120, 0xc000071f20, 0xc000030000, 0x0)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2525 +0x312
cmd/link/internal/loader.(*Loader).LoadFull(0xc000065c00, 0x86c760, 0xc00000c120, 0x0)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2088 +0x1cf
cmd/link/internal/ld.(*Link).loadlibfull(0xc000065880, 0xc0016ce000, 0x15ae3, 0x15ae3, 0x2d0000)
	/usr/local/go/src/cmd/link/internal/ld/lib.go:2835 +0x73
cmd/link/internal/ld.Main(0x86c760, 0x20, 0x20, 0x1, 0x7, 0x10, 0x0, 0x0, 0x6d87b2, 0x1b, ...)
	/usr/local/go/src/cmd/link/internal/ld/main.go:341 +0x18cc
main.main()
	/usr/local/go/src/cmd/link/main.go:68 +0x1dc
FAIL	mellium.im/xmpp/x509 [build failed]

[ianlancetaylor]

CC @cherrymui @thanm

Always hard to know what to do with a failure that only happened once, but perhaps the stack backtrace will suggest something.

[thanm]

This is another one of those stack traces that seems impossible, very similar to #42658.

If this is happening on the same machine as #42658 I would consider running a memory test on that machine (memtest86 or equivalent).

[SamWhited]

If this is happening on the same machine as #42658 I would consider running a memory test on that machine (memtest86 or equivalent).

I tried to have that happen already, unfortunately the person who runs the CI system just said it was unlikely to be a memory issue and they had no other indications that this machine had problems and they weren't going to do it.

EDIT: I have followed up with them to try and convince them again and will let you know if they agree to run memtest. They did agree to discuss it at least.

[cherrymui]

Yeah. I think the linker, at least this part, is pretty deterministic. So if it happens nondeterministically, my guess is that the problem may be somewhere else, memory corruption (it could be the machine, the kernel, or could be the Go runtime), or object file corruption.

[SamWhited]

I just had this exact same one happen again on another build; if it were just random hardware failures I wouldn't expect it to fail in the exact same place (though of course, they are the exact same tests behaving in exactly the same way on the same VM image on the same host machine so I suppose it's possible)

[SamWhited]

More possibly related weirdness (that shows the same behavior as the others when I try to reproduce it):

unexpected fault address 0x520b42
fatal error: fault
[signal SIGBUS: bus error code=0x3 addr=0x520b42 pc=0x520b42]

goroutine 1 [running]:
runtime.throw(0x6cd22b, 0x5)
	/usr/local/go/src/runtime/panic.go:1116 +0x72 fp=0xc0000bab30 sp=0xc0000bab00 pc=0x435912
runtime.sigpanic()
	/usr/local/go/src/runtime/signal_unix.go:739 +0x465 fp=0xc0000bab60 sp=0xc0000bab30 pc=0x44c025
cmd/link/internal/loader.(*Loader).migrateAttributes(0xc000093c00, 0x7653, 0x4004d4001cd4001d)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2655 +0x62 fp=0xc0000babf0 sp=0xc0000bab60 pc=0x520b42
cmd/link/internal/loader.loadObjFull(0xc000093c00, 0xc0000abe00, 0xc000a90000)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2750 +0x127 fp=0xc0000baca0 sp=0xc0000babf0 pc=0x521a47
cmd/link/internal/loader.(*Loader).LoadFull(0xc000093c00, 0x86c760, 0xc00009a0c0, 0x0)
	/usr/local/go/src/cmd/link/internal/loader/loader.go:2156 +0xf77 fp=0xc0000badb8 sp=0xc0000baca0 pc=0x51e8d7
cmd/link/internal/ld.(*Link).loadlibfull(0xc000093880, 0xc000f20000, 0x115c2, 0x115c2, 0x250000)
	/usr/local/go/src/cmd/link/internal/ld/lib.go:2835 +0x73 fp=0xc0000baeb8 sp=0xc0000badb8 pc=0x5d29f3
cmd/link/internal/ld.Main(0x86c760, 0x20, 0x20, 0x1, 0x7, 0x10, 0x0, 0x0, 0x6d87b2, 0x1b, ...)
	/usr/local/go/src/cmd/link/internal/ld/main.go:341 +0x18cc fp=0xc0000bb118 sp=0xc0000baeb8 pc=0x5e0b0c
main.main()
	/usr/local/go/src/cmd/link/main.go:68 +0x1dc fp=0xc0000bbf88 sp=0xc0000bb118 pc=0x65bd3c
runtime.main()
	/usr/local/go/src/runtime/proc.go:204 +0x209 fp=0xc0000bbfe0 sp=0xc0000bbf88 pc=0x438109
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000bbfe8 sp=0xc0000bbfe0 pc=0x469b21
FAIL	mellium.im/xmpp/internal/attr [build failed]

[thanm]

If the traceback is to be believed, the third argument to loader.(*Loader).migrateAttributes is trashed (should be a sym.Symbol on the heap). This is even more similar to #42658 -- there it was a weird small value, here it is a weird huge value.

Again, if there is any way you can get this to happen more reliably/reproducibly that would be a big help.

[SamWhited]

I can always re-submit CI over and over again until it happens, I suppose. I have now seen it on two separate CI runners, so it's unlikely to be memory corruption on that one box.

[fernape]

I have a quasi-reproducible crash similar to that:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x50 pc=0x520b42]

goroutine 1 [running]:
cmd/link/internal/loader.(*Loader).migrateAttributes(0xc0000a8000, 0x3d11, 0x30)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2655 +0x62
cmd/link/internal/loader.loadObjFull(0xc0000a8000, 0xc0000adc20, 0xc001130000)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2750 +0x127
cmd/link/internal/loader.(*Loader).LoadFull(0xc0000a8000, 0x86c760, 0xc00000c120, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2156 +0xf77
cmd/link/internal/ld.(*Link).loadlibfull(0xc000075880, 0xc001ec6000, 0x18ee9, 0x18ee9, 0x3e0000)
        /usr/local/go/src/cmd/link/internal/ld/lib.go:2835 +0x73
cmd/link/internal/ld.Main(0x86c760, 0x20, 0x20, 0x1, 0x7, 0x10, 0x0, 0x0, 0x6d87b2, 0x1b, ...)
        /usr/local/go/src/cmd/link/internal/ld/main.go:341 +0x18cc
main.main()
        /usr/local/go/src/cmd/link/main.go:68 +0x1dc
do:     nncp-xfer: got exit code 2
do:   all: got exit code 1
do: all: got exit code 1

FreeBSD 13-current in VirtualBox:

$ uname -a
FreeBSD vm-current 13.0-CURRENT FreeBSD 13.0-CURRENT #9 main-c255861-gd1eb05aa0c3a: Tue Jan 12 02:48:45 CET 2021     root@vm-current:/usr/obj/usr/src/amd64.amd64/sys/GENERIC  amd64

Go version:

$ pkg info go
go-1.15.6,1
Name           : go
Version        : 1.15.6,1
Installed on   : Thu Jan 14 10:04:05 2021 CET
Origin         : lang/go
Architecture   : FreeBSD:13:amd64
Prefix         : /usr/local
Categories     : lang
Licenses       : BSD3CLAUSE
Maintainer     : dmgk@FreeBSD.org
WWW            : https://golang.org
Comment        : Go programming language
Annotations    :
        FreeBSD_version: 1300134
        repo_type      : binary
        repository     : FreeBSD
Flat size      : 283MiB
Description    :
Go is an open source programming environment that makes it easy to build
simple, reliable, and efficient software.

WWW: https://golang.org

Go env:

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/fernape/.cache/go-build"
GOENV="/home/fernape/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="freebsd"
GOINSECURE=""
GOMODCACHE="/home/fernape/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="freebsd"
GOPATH="/home/fernape/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/freebsd_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build273454518=/tmp/go-build -gno-record-gcc-switches"

How to reproduce:

[fernape@vm-current ~/tmp]$ fetch http://www.nncpgo.org/download/nncp-5.5.1.tar.xz
nncp-5.5.1.tar.xz                                     1165 kB  916 kBps    01s
[fernape@vm-current ~/tmp]$ tar xvzf nncp-5.5.1.tar.xz &> /dev/null
[fernape@vm-current ~/tmp]$ cd nncp-5.5.1
[fernape@vm-current ~/tmp/nncp-5.5.1]$ ./contrib/do -c all
do  all
do    bin/all
do      bin/nncp-bundle
do        gopath
do      bin/nncp-call
do      bin/nncp-caller
do      bin/nncp-cfgenc
# go.cypherpunks.ru/nncp/v5/cmd/nncp-cfgenc
panic: sym already present in installSym

goroutine 1 [running]:
cmd/link/internal/loader.(*Loader).installSym(...)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2447
cmd/link/internal/loader.(*Loader).addNewSym(0xc0004fe000, 0xbf33, 0x0, 0x0, 0x0, 0xc00073a6c0, 0xffffffffffffff34, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2465 +0x245
cmd/link/internal/loader.loadObjSyms(0xc0004fe000, 0xc00000c120, 0xc00071e480, 0xc000080000, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2525 +0x312
cmd/link/internal/loader.(*Loader).LoadFull(0xc0004fe000, 0x86c760, 0xc00000c120, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2088 +0x1cf
cmd/link/internal/ld.(*Link).loadlibfull(0xc00006d880, 0xc001b12000, 0x18c60, 0x18c60, 0x350000)
        /usr/local/go/src/cmd/link/internal/ld/lib.go:2835 +0x73
cmd/link/internal/ld.Main(0x86c760, 0x20, 0x20, 0x1, 0x7, 0x10, 0x0, 0x0, 0x6d87b2, 0x1b, ...)
        /usr/local/go/src/cmd/link/internal/ld/main.go:341 +0x18cc
main.main()
        /usr/local/go/src/cmd/link/main.go:68 +0x1dc
do:     nncp-cfgenc: got exit code 2
do:   all: got exit code 1
do: all: got exit code 1
[fernape@vm-current ~/tmp/nncp-5.5.1]$

Notice how the error varies as it does the point of failure.

Completely unable to reproduce in 11.4amd64, 11.4i386, 12.2amd64, 12.2i386.

The 13-current virtualized machine has 16 GB of RAM assigned and I increased it to 20 just in case, but that doesn't seem to make any difference. There is plenty of disk space. This same virtualized machine built over 300 packages (llvm, gcc, cmake...) without problems the very same day. I don't think memory is bad. The physical machine in which this VirtualBox 13-current runs also builds packages without any problems.

Just after a couple of minutes:

[fernape@vm-current ~/tmp]$ rm -rf *
[fernape@vm-current ~/tmp]$ fetch http://www.nncpgo.org/download/nncp-5.5.1.tar.xz
nncp-5.5.1.tar.xz                                     1165 kB 1234 kBps    01s
[fernape@vm-current ~/tmp]$ tar xvzf nncp-5.5.1.tar.xz &> /dev/null
[fernape@vm-current ~/tmp]$ cd -
/home/fernape/tmp/nncp-5.5.1
[fernape@vm-current ~/tmp/nncp-5.5.1]$ ./contrib/do -c all
do  all
do    bin/all
do      bin/nncp-bundle
do        gopath
do      bin/nncp-call
do      bin/nncp-caller
do      bin/nncp-cfgenc
do      bin/nncp-cfgmin
do      bin/nncp-cfgnew
do      bin/nncp-check
do      bin/nncp-daemon
do      bin/nncp-exec
do      bin/nncp-file
do      bin/nncp-freq
do      bin/nncp-log
do      bin/nncp-pkt
do      bin/nncp-reass
do      bin/nncp-rm
do      bin/nncp-stat
do      bin/nncp-toss
do      bin/nncp-xfer
do: Removing stamp files...
[fernape@vm-current ~/tmp/nncp-5.5.1]$

I removed the directory and try again and it failed with:

[fernape@vm-current ~/tmp/nncp-5.5.1]$ ./contrib/do -c all
do  all
do    bin/all
do      bin/nncp-bundle
do        gopath
do      bin/nncp-call
do      bin/nncp-caller
# go.cypherpunks.ru/nncp/v5/cmd/nncp-caller
panic: sym already present in installSym

goroutine 1 [running]:
cmd/link/internal/loader.(*Loader).installSym(...)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2447
cmd/link/internal/loader.(*Loader).addNewSym(0xc000075c00, 0xbfd9, 0x0, 0x0, 0x0, 0xc0008805a0, 0xffffffffffffff34, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2465 +0x245
cmd/link/internal/loader.loadObjSyms(0xc000075c00, 0xc00000c160, 0xc000824c60, 0xc000030000, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2525 +0x312
cmd/link/internal/loader.(*Loader).LoadFull(0xc000075c00, 0x86c760, 0xc00000c160, 0x0)
        /usr/local/go/src/cmd/link/internal/loader/loader.go:2088 +0x1cf
cmd/link/internal/ld.(*Link).loadlibfull(0xc000075880, 0xc001094000, 0x19318, 0x19318, 0x530000)
        /usr/local/go/src/cmd/link/internal/ld/lib.go:2835 +0x73
cmd/link/internal/ld.Main(0x86c760, 0x20, 0x20, 0x1, 0x7, 0x10, 0x0, 0x0, 0x6d87b2, 0x1b, ...)
        /usr/local/go/src/cmd/link/internal/ld/main.go:341 +0x18cc
main.main()
        /usr/local/go/src/cmd/link/main.go:68 +0x1dc
do:     nncp-caller: got exit code 2
do:   all: got exit code 1
do: all: got exit code 1