Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: segfault in sync.Pool when using a shared runtime #24640

Closed
otavio opened this issue Apr 2, 2018 · 24 comments
Closed

runtime: segfault in sync.Pool when using a shared runtime #24640

otavio opened this issue Apr 2, 2018 · 24 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@otavio
Copy link

otavio commented Apr 2, 2018

QPlease answer these questions before submitting your issue. Thanks!

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

1.10

Does this issue reproduce with the latest release?

Yes.

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

Reproducible on ARM and x86_64 under Linux

What did you do?

https://bugzilla.yoctoproject.org/show_bug.cgi?id=12631#c10

@bcmills
Copy link
Contributor

bcmills commented Apr 2, 2018

The original post from the linked bug report:

The following code:

package main

import (
	"net/http"

	"github.com/sirupsen/logrus"
)

func main() {
	logrus.Info("starting")

	client := &http.Client{}
	r, _ := http.NewRequest("GET", "https://google.com", nil)

	client.Do(r)

	logrus.Info("started")
}

Works when using 1.9.4 and fails with 1.10. However, when using Go from our host to cross build it for same target, it works fine.

@bcmills
Copy link
Contributor

bcmills commented Apr 2, 2018

On that bug report, Matt Madison (perhaps @madisongh?) notes:

I can reproduce this now on an ARMv7 target, provided the image also includes the ca-certificates package. Also, you have to wait until /dev/random has enough entropy.

I can also reproduce this natively by building go 1.10 from source, building a shared runtime with go install -linkshared -buildmode=shared std, and doing a go get -linkshared github.com/gustavosbarreto/go-crazy. So it's not ARM-specific.

It's a panic due to a segfault, always appearing to happen around a sync.Pool request in logrus's Entry.log function. However, it only seems to happen if the https request is also getting processed in other goroutines. Panic tracebacks always point to the logrus package as the running thread, sometimes with and sometimes without other goroutines being active.

It does seem to happen only when the program is linked against shared runtime, not when linked statically.

Definitely an upstream issue, just not 100% sure that it's really in the Go runtime, or if logrus is misusing the sync package.

And later:

I haven't found an upstream bug report that matches this exactly, and it's hard to know whether the root cause is in the go shared runtime support or in the logrus package.

Some possibly related issues:
#23199
sirupsen/logrus#740
https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=1561619

@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 2, 2018
@bcmills bcmills changed the title Go 1.10.1 generates invalid code when using a shared runtime runtime: segfault in sync.Pool when using a shared runtime Apr 2, 2018
@bcmills bcmills added this to the Go1.11 milestone Apr 2, 2018
@bcmills
Copy link
Contributor

bcmills commented Apr 2, 2018

(@aclements, @randall77: any ideas? The initial bugreport theorizes that the compiler may be generating invalid code.)

@otavio
Copy link
Author

otavio commented Apr 2, 2018

Shouldn't this be tagged for 1.10.2 release? It is a regression after all.

@bcmills
Copy link
Contributor

bcmills commented Apr 2, 2018

That probably depends on what the root cause turns out to be and how invasive the fix is. But sure, we can tag it for 1.10.2 until we figure that out.

@bcmills bcmills modified the milestones: Go1.11, Go1.10.2 Apr 2, 2018
@bradfitz
Copy link
Contributor

bradfitz commented Apr 4, 2018

Where is the stack trace?

It should be in this bug. I also don't see it in the linked bugzilla bug.

@madisongh
Copy link

Stack traces from a few sample runs:

Example 1:

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

goroutine 1 [running]:
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.Entry.log(0xc4203be230, 0xc4201f2180, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc400000004, ...)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/entry.go:99 +0x28c
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.(*Entry).Info(0xc4201ba0a0, 0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/entry.go:153 +0xac
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.(*Logger).Info(0xc4203be230, 0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/logger.go:189 +0x70
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.Info(0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/exported.go:87 +0x50
main.main()
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/main.go:18 +0x10b

Example 2:

runtime: nameOff 0x5 base 0xc4201face0 not in ranges:
	types 0x7fccccb23980 etypes 0x7fccccf5e6e0
	types 0x616040 etypes 0x61b1c8
fatal error: runtime: name offset base pointer out of range

goroutine 1 [running]:
runtime.throw(0x7fcccc8a1815, 0x2e)
	/sources/go-1.10/go/src/runtime/panic.go:619 +0x83 fp=0xc420375cb0 sp=0xc420375c90 pc=0x7fcccc269fe3
runtime.resolveNameOff(0xc4201face0, 0xc400000005, 0x41012f)
	/sources/go-1.10/go/src/runtime/type.go:193 +0x229 fp=0xc420375d18 sp=0xc420375cb0 pc=0x7fcccc298949
runtime.(*_type).nameOff(0xc4201face0, 0xc400000005, 0x7fcccc2c3764)
	/sources/go-1.10/go/src/runtime/type.go:199 +0x35 fp=0xc420375d40 sp=0xc420375d18 pc=0x7fcccc298a35
runtime.(*_type).string(0xc4201face0, 0x7fcccc2c34d6, 0xc42042c240)
	/sources/go-1.10/go/src/runtime/type.go:46 +0x38 fp=0xc420375d68 sp=0xc420375d40 pc=0x7fcccc298438
runtime.panicdottypeE(0xc4201face0, 0x7fccccf0b040, 0x619260)
	/sources/go-1.10/go/src/runtime/iface.go:242 +0x187 fp=0xc420375dc0 sp=0xc420375d68 pc=0x7fcccc248347
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.Entry.log(0xc4203be230, 0xc4201de720, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc400000004, ...)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/entry.go:99 +0x28c fp=0xc420375e30 sp=0xc420375dc0 pc=0x40e5cc
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.(*Entry).Info(0xc4201d74f0, 0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/entry.go:153 +0xac fp=0xc420375ea0 sp=0xc420375e30 pc=0x40ebac
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.(*Logger).Info(0xc4203be230, 0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/logger.go:189 +0x70 fp=0xc420375ed8 sp=0xc420375ea0 pc=0x410cb0
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.Info(0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/exported.go:87 +0x50 fp=0xc420375f08 sp=0xc420375ed8 pc=0x40fdd0
main.main()
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/main.go:18 +0x10b fp=0xc420375f88 sp=0xc420375f08 pc=0x41450b
runtime.main()
	/sources/go-1.10/go/src/runtime/proc.go:198 +0x24f fp=0xc420375fe0 sp=0xc420375f88 pc=0x7fcccc26c78f
runtime.goexit()
	/sources/go-1.10/go/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420375fe8 sp=0xc420375fe0 pc=0x7fcccc2a20e1

goroutine 13 [IO wait]:
internal/poll.runtime_pollWait(0x7fccc879fe30, 0x72, 0xc4204f18b8)
	/sources/go-1.10/go/src/runtime/netpoll.go:173 +0x59
internal/poll.(*pollDesc).wait(0xc4204e8198, 0x72, 0xffffffffffffff00, 0x61af80, 0x7fcccd2983c0)
	/sources/go-1.10/go/src/internal/poll/fd_poll_runtime.go:85 +0xa1
internal/poll.(*pollDesc).waitRead(0xc4204e8198, 0xc4200fc000, 0x800, 0x800)
	/sources/go-1.10/go/src/internal/poll/fd_poll_runtime.go:90 +0x3f
internal/poll.(*FD).Read(0xc4204e8180, 0xc4200fc000, 0x800, 0x800, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/internal/poll/fd_unix.go:157 +0x17f
net.(*netFD).Read(0xc4204e8180, 0xc4200fc000, 0x800, 0x800, 0xc420382170, 0x7fcccce93b20, 0xc4205bd3c0)
	/sources/go-1.10/go/src/net/fd_unix.go:202 +0x51
net.(*conn).Read(0xc4204b6018, 0xc4200fc000, 0x800, 0x800, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/net/net.go:176 +0x6c
crypto/tls.(*block).readFromUntil(0xc4204b2270, 0x7fccc86db000, 0xc4204b6018, 0x5, 0xc4204b6018, 0xc4204b2270)
	/sources/go-1.10/go/src/crypto/tls/conn.go:493 +0x98
crypto/tls.(*Conn).readRecord(0xc420382000, 0x7fccccf3e317, 0xc420382120, 0x7fcccde2dee0)
	/sources/go-1.10/go/src/crypto/tls/conn.go:595 +0xe2
crypto/tls.(*Conn).Read(0xc420382000, 0xc420612000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/crypto/tls/conn.go:1156 +0x102
bufio.(*Reader).Read(0xc4203330e0, 0xc4203c3a64, 0xe45, 0xe45, 0x564, 0x0, 0x0)
	/sources/go-1.10/go/src/bufio/bufio.go:216 +0x250
io.ReadAtLeast(0x7fccccf462e0, 0xc4203330e0, 0xc4203c3500, 0x13a9, 0x13a9, 0x13a9, 0x13a9, 0xc42058e8c0, 0xc42058e910)
	/sources/go-1.10/go/src/io/io.go:309 +0x88
io.ReadFull(0x7fccccf462e0, 0xc4203330e0, 0xc4203c3500, 0x13a9, 0x13a9, 0x13a900080001, 0x7fcc00000001, 0x0)
	/sources/go-1.10/go/src/io/io.go:327 +0x5a
net/http.(*http2Framer).ReadFrame(0xc42058e8c0, 0xc4201de630, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/net/http/h2_bundle.go:1783 +0x161
net/http.(*http2clientConnReadLoop).run(0xc4204f1fb8, 0x7fccccf33558, 0xc42045a7b8)
	/sources/go-1.10/go/src/net/http/h2_bundle.go:8028 +0x92
net/http.(*http2ClientConn).readLoop(0xc42015b180)
	/sources/go-1.10/go/src/net/http/h2_bundle.go:7956 +0x6a
created by net/http.(*http2Transport).newClientConn
	/sources/go-1.10/go/src/net/http/h2_bundle.go:7143 +0x699

Example 3:

unexpected fault address 0x0
fatal error: fault
[signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x7f0e5b205428]

goroutine 1 [running]:
runtime.throw(0x7f0e5b7ec7c8, 0x5)
	/sources/go-1.10/go/src/runtime/panic.go:619 +0x83 fp=0xc420375cf0 sp=0xc420375cd0 pc=0x7f0e5b1d6fe3
runtime.sigpanic()
	/sources/go-1.10/go/src/runtime/signal_unix.go:395 +0x215 fp=0xc420375d40 sp=0xc420375cf0 pc=0x7f0e5b1f0f55
runtime.(*_type).string(0x46524553552d4e54, 0x7f0e5b2304d6, 0xc42042c240)
	/sources/go-1.10/go/src/runtime/type.go:46 +0x28 fp=0xc420375d68 sp=0xc420375d40 pc=0x7f0e5b205428
runtime.panicdottypeE(0x46524553552d4e54, 0x7f0e5be78040, 0x619260)
	/sources/go-1.10/go/src/runtime/iface.go:242 +0x187 fp=0xc420375dc0 sp=0xc420375d68 pc=0x7f0e5b1b5347
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.Entry.log(0xc4203be230, 0xc420045470, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc400000004, ...)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/entry.go:99 +0x28c fp=0xc420375e30 sp=0xc420375dc0 pc=0x40e5cc
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.(*Entry).Info(0xc420591360, 0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/entry.go:153 +0xac fp=0xc420375ea0 sp=0xc420375e30 pc=0x40ebac
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.(*Logger).Info(0xc4203be230, 0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/logger.go:189 +0x70 fp=0xc420375ed8 sp=0xc420375ea0 pc=0x410cb0
github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus.Info(0xc420375f58, 0x1, 0x1)
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/vendor/github.com/sirupsen/logrus/exported.go:87 +0x50 fp=0xc420375f08 sp=0xc420375ed8 pc=0x40fdd0
main.main()
	/sources/logrus-test/src/github.com/gustavosbarreto/go-crazy/main.go:18 +0x10b fp=0xc420375f88 sp=0xc420375f08 pc=0x41450b
runtime.main()
	/sources/go-1.10/go/src/runtime/proc.go:198 +0x24f fp=0xc420375fe0 sp=0xc420375f88 pc=0x7f0e5b1d978f
runtime.goexit()
	/sources/go-1.10/go/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420375fe8 sp=0xc420375fe0 pc=0x7f0e5b20f0e1

goroutine 15 [IO wait]:
internal/poll.runtime_pollWait(0x7f0e5870ef00, 0x72, 0xc4201eb8b8)
	/sources/go-1.10/go/src/runtime/netpoll.go:173 +0x59
internal/poll.(*pollDesc).wait(0xc4204d6118, 0x72, 0xffffffffffffff00, 0x61af80, 0x7f0e5c2053c0)
	/sources/go-1.10/go/src/internal/poll/fd_poll_runtime.go:85 +0xa1
internal/poll.(*pollDesc).waitRead(0xc4204d6118, 0xc4201aa000, 0x800, 0x800)
	/sources/go-1.10/go/src/internal/poll/fd_poll_runtime.go:90 +0x3f
internal/poll.(*FD).Read(0xc4204d6100, 0xc4201aa000, 0x800, 0x800, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/internal/poll/fd_unix.go:157 +0x17f
net.(*netFD).Read(0xc4204d6100, 0xc4201aa000, 0x800, 0x800, 0xc420446170, 0x7f0e5be00b20, 0xc420103060)
	/sources/go-1.10/go/src/net/fd_unix.go:202 +0x51
net.(*conn).Read(0xc4203bc018, 0xc4201aa000, 0x800, 0x800, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/net/net.go:176 +0x6c
crypto/tls.(*block).readFromUntil(0xc42044c090, 0x7f0e5870f0d8, 0xc4203bc018, 0x5, 0xc4203bc018, 0xc42044c090)
	/sources/go-1.10/go/src/crypto/tls/conn.go:493 +0x98
crypto/tls.(*Conn).readRecord(0xc420446000, 0x7f0e5beab317, 0xc420446120, 0x7f0e5cd9aee0)
	/sources/go-1.10/go/src/crypto/tls/conn.go:595 +0xe2
crypto/tls.(*Conn).Read(0xc420446000, 0xc420194000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/crypto/tls/conn.go:1156 +0x102
bufio.(*Reader).Read(0xc4203e1320, 0xc4203c3a64, 0xdc2, 0xdc2, 0x564, 0x0, 0x0)
	/sources/go-1.10/go/src/bufio/bufio.go:216 +0x250
io.ReadAtLeast(0x7f0e5beb32e0, 0xc4203e1320, 0xc4203c3500, 0x1326, 0x1326, 0x1326, 0x1326, 0xc4201c1b20, 0xc4201c1b70)
	/sources/go-1.10/go/src/io/io.go:309 +0x88
io.ReadFull(0x7f0e5beb32e0, 0xc4203e1320, 0xc4203c3500, 0x1326, 0x1326, 0x132600080001, 0x7f0e00000001, 0x0)
	/sources/go-1.10/go/src/io/io.go:327 +0x5a
net/http.(*http2Framer).ReadFrame(0xc4201c1b20, 0xc420045380, 0x0, 0x0, 0x0)
	/sources/go-1.10/go/src/net/http/h2_bundle.go:1783 +0x161
net/http.(*http2clientConnReadLoop).run(0xc4201ebfb8, 0x7f0e5bea0558, 0xc4204597b8)
	/sources/go-1.10/go/src/net/http/h2_bundle.go:8028 +0x92
net/http.(*http2ClientConn).readLoop(0xc42011b6c0)
	/sources/go-1.10/go/src/net/http/h2_bundle.go:7956 +0x6a
created by net/http.(*http2Transport).newClientConn
	/sources/go-1.10/go/src/net/http/h2_bundle.go:7143 +0x699

@otavio
Copy link
Author

otavio commented Apr 11, 2018

Any idea how we can debug this?

@ianlancetaylor
Copy link
Contributor

Have you run the program under the race detector?

@ianlancetaylor
Copy link
Contributor

In stack trace 3 above it's clear that a value that should be a pointer to a type structure is actually a string. So memory is being corrupted somewhere. The first guesses are always the race detector or invalid use of cgo.

halstead pushed a commit to openembedded/openembedded-core that referenced this issue Apr 13, 2018
For the time being, there is a serious bug[1] in Go 1.10 when it comes to
use the shared runtime support which cases problems in multiple projects.

 1. golang/go#24640

It is still unclear if the problem arises from a bug inside the
compiler itself or it makes a real problem more visible. Either way,
using 1.10 as default seems to be a risk so we are changing back to
1.9 for now.

Refs: [YOCTO: #12631]

Signed-off-by: Otavio Salvador <otavio@ossystems.com.br>
Signed-off-by: Ross Burton <ross.burton@intel.com>
gbionescu pushed a commit to gbionescu/poky that referenced this issue Apr 13, 2018
For the time being, there is a serious bug[1] in Go 1.10 when it comes to
use the shared runtime support which cases problems in multiple projects.

 1. golang/go#24640

It is still unclear if the problem arises from a bug inside the
compiler itself or it makes a real problem more visible. Either way,
using 1.10 as default seems to be a risk so we are changing back to
1.9 for now.

Refs: [YOCTO: #12631]

(From OE-Core rev: c5b5055d2dc04317a7a64c150046a6435a6805c2)

Signed-off-by: Otavio Salvador <otavio@ossystems.com.br>
Signed-off-by: Ross Burton <ross.burton@intel.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
jpuhlman pushed a commit to MontaVista-OpenSourceTechnology/poky that referenced this issue Apr 21, 2018
Source: poky
MR: 00000
Type: Integration
Disposition: Merged from poky
ChangeID: f6d8c3f
Description:

For the time being, there is a serious bug[1] in Go 1.10 when it comes to
use the shared runtime support which cases problems in multiple projects.

 1. golang/go#24640

It is still unclear if the problem arises from a bug inside the
compiler itself or it makes a real problem more visible. Either way,
using 1.10 as default seems to be a risk so we are changing back to
1.9 for now.

Refs: [YOCTO: #12631]

(From OE-Core rev: c5b5055d2dc04317a7a64c150046a6435a6805c2)

Signed-off-by: Otavio Salvador <otavio@ossystems.com.br>
Signed-off-by: Ross Burton <ross.burton@intel.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Signed-off-by: Jeremy Puhlman <jpuhlman@mvista.com>
jpuhlman pushed a commit to MontaVista-OpenSourceTechnology/poky that referenced this issue Apr 21, 2018
Source: poky
MR: 00000
Type: Integration
Disposition: Merged from poky
ChangeID: f6d8c3f
Description:

For the time being, there is a serious bug[1] in Go 1.10 when it comes to
use the shared runtime support which cases problems in multiple projects.

 1. golang/go#24640

It is still unclear if the problem arises from a bug inside the
compiler itself or it makes a real problem more visible. Either way,
using 1.10 as default seems to be a risk so we are changing back to
1.9 for now.

Refs: [YOCTO: #12631]

(From OE-Core rev: c5b5055d2dc04317a7a64c150046a6435a6805c2)

Signed-off-by: Otavio Salvador <otavio@ossystems.com.br>
Signed-off-by: Ross Burton <ross.burton@intel.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Signed-off-by: Jeremy Puhlman <jpuhlman@mvista.com>
@FiloSottile
Copy link
Contributor

@gopherbot please open a backport tracking issue for 1.10.

@gopherbot
Copy link

Backport issue(s) opened: #25037 (for 1.10).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

@FiloSottile FiloSottile modified the milestones: Go1.10.2, Go1.11 Apr 24, 2018
@ianlancetaylor ianlancetaylor added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jul 10, 2018
@ianlancetaylor ianlancetaylor modified the milestones: Go1.11, Go1.12 Jul 10, 2018
@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@jasonkim
Copy link

jasonkim commented Apr 4, 2019

This is still a problem with go 1.11.

@aclements
Copy link
Member

@jasonkim, we still need more information to debug this. Since it sounds like you can reproduce it, can you provide stack traces and try running under the race detector?

@otavio
Copy link
Author

otavio commented Apr 5, 2019

We could only get this going disabling the dynamic linking of runtime.

@jasonkim
Copy link

jasonkim commented Apr 8, 2019

I tried adding -race to the build/install step and got the following error.

go install: -race is only supported on linux/amd64, linux/ppc64le, freebsd/amd64, netbsd/amd64, darwin/amd64 and windows/amd64

What is there to do for this? I'm assuming since my env is an ARM based, the race detector won't work?

@ianlancetaylor
Copy link
Contributor

Can you try the same program on amd64 with the race detector?

Either way, can you provide stack traces? We don't have enough information here to identify the problem.

@ianlancetaylor ianlancetaylor reopened this Apr 8, 2019
@jasonkim
Copy link

jasonkim commented Apr 9, 2019

Here's a couple logs I saw during my testing. These are pretty representative as all the other ones I saw were pretty much the same. It seems to occur when mqtt is connecting (in go routine?) and log happens at/near the same time.
I've scrubbed some of the details, but should still make sense.

Log 1

hub_1      | panic: runtime error: invalid memory address or nil pointer dereference
hub_1      | [signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x557d72]
hub_1      |
hub_1      | goroutine 1 [running]:
hub_1      | github.com/sirupsen/logrus.(*Entry).write(0xc42007ee10)
hub_1      | 	/go/src/github.com/sirupsen/logrus/entry.go:128 +0x42
hub_1      | github.com/sirupsen/logrus.Entry.log(0xc42007eaf0, 0xc420077f50, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x4, ...)
hub_1      | 	/go/src/github.com/sirupsen/logrus/entry.go:104 +0x1a6
hub_1      | github.com/sirupsen/logrus.(*Entry).Info(0xc42007edc0, 0xc420163638, 0x1, 0x1)
hub_1      | 	/go/src/github.com/sirupsen/logrus/entry.go:153 +0xac
hub_1      | github.com/sirupsen/logrus.(*Entry).Infoln(0xc42007edc0, 0xc4200f4dc0, 0x2, 0x2)
hub_1      | 	/go/src/github.com/sirupsen/logrus/entry.go:244 +0xe0
hub_1      | github.com/sirupsen/logrus.(*Entry).Println(0xc42007edc0, 0xc4200f4dc0, 0x2, 0x2)
hub_1      | 	/go/src/github.com/sirupsen/logrus/entry.go:249 +0x49
hub_1      | github.com/sirupsen/logrus.(*Logger).Println(0xc42007eaf0, 0xc4200f4dc0, 0x2, 0x2)
hub_1      | 	/go/src/github.com/sirupsen/logrus/logger.go:259 +0x5c
hub_1      | github.com/eclipse/paho%2emqtt%2egolang.(*client).Connect(0xc420148380, 0xef7e80, 0xc420148380)
hub_1      | 	/go/src/github.com/eclipse/paho.mqtt.golang/client.go:189 +0xfb
hub_1      | b/hub/api/mqtt.(*Client).connect(0xc4200103c0, 0x0, 0x0)
hub_1      | 	/go/src/b/hub/api/mqtt/mqtt.go:123 +0x1e7
hub_1      | b/hub/api/mqtt.(*Client).waitForConnection(0xc4200103c0)
hub_1      | 	/go/src/b/hub/api/mqtt/mqtt.go:88 +0x78
hub_1      | b/hub/api/mqtt.(*Client).Start(0xc4200103c0)
hub_1      | 	/go/src/b/hub/api/mqtt/mqtt.go:82 +0x2b
hub_1      | main.main()
hub_1      | 	/go/src/b/cmd/hub/main.go:59 +0x129

Log 2

Apr 04 21:23:52 [macaddr] thing1[2407]: fatal error: panic while printing panic value
Apr 04 21:23:52 [macaddr] thing1[2407]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x218 pc=0xb6177fcc]
Apr 04 21:23:52 [macaddr] thing1[2407]: goroutine 1 [running]:
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.throw(0xb674fb2f, 0x20)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/panic.go:608 +0x64 fp=0x856d7af4 sp=0x856d7ae0 pc=0xb6145920
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.preprintpanics.func1()
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/panic.go:415 +0x44 fp=0x856d7b04 sp=0x856d7af4 pc=0xb617d9cc
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.call16(0x0, 0xb6b411b0, 0x0, 0x0, 0x0)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/asm_arm.s:519 +0x4c fp=0x856d7b18 sp=0x856d7b04 pc=0xb617f75c
Apr 04 21:23:52 [macaddr] thing1[2407]: panic(0xb6ab77f8, 0xb6f55aa0)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/panic.go:513 +0x1bc fp=0x856d7b60 sp=0x856d7b18 pc=0xb6145448
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.panicmem()
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/panic.go:82 +0x74 fp=0x856d7b6c sp=0x856d7b60 pc=0xb6144234
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.sigpanic()
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/signal_unix.go:390 +0xec fp=0x856d7b90 sp=0x856d7b6c pc=0xb6161cc8
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.(*_type).string(0x200, 0xb69150d3, 0xd)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/type.go:46 +0x14 fp=0x856d7ba4 sp=0x856d7b94 pc=0xb6177fcc
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.(*TypeAssertionError).Error(0x85868300, 0xb6abad68, 0x85868300)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/error.go:39 +0x6c fp=0x856d7c5c sp=0x856d7ba4 pc=0xb6114530
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.preprintpanics(0x856d7ccc)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/panic.go:421 +0xac fp=0x856d7c98 sp=0x856d7c5c pc=0xb6145040
Apr 04 21:23:52 [macaddr] thing1[2407]: panic(0xb6abad68, 0x85868300)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/panic.go:554 +0x2ec fp=0x856d7ce0 sp=0x856d7c98 pc=0xb6145578
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.panicdottypeE(0x200, 0xb6b259b8, 0x4316e0)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/iface.go:248 +0xe8 fp=0x856d7cec sp=0x856d7ce0 pc=0xb6119848
Apr 04 21:23:52 [macaddr] thing1[2407]: github.com/sirupsen/logrus.Entry.log(0x85658120, 0x858682e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/sirupsen/logrus/entry.go:101 +0x564 fp=0x856d7d6c sp=0x856d7cec pc=0x4252f8
Apr 04 21:23:52 [macaddr] thing1[2407]: github.com/sirupsen/logrus.(*Entry).Error(0x854f8ea0, 0x856d7dd4, 0x1, 0x1)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/sirupsen/logrus/entry.go:156 +0x88 fp=0x856d7dac sp=0x856d7d6c pc=0x425664
Apr 04 21:23:52 [macaddr] thing1[2407]: github.com/sirupsen/logrus.(*Entry).Errorf(0x854f8ea0, 0x42b884, 0x44, 0x856d7ea8, 0x1, 0x1)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/sirupsen/logrus/entry.go:204 +0xc0 fp=0x856d7ddc sp=0x856d7dac pc=0x425c14
Apr 04 21:23:52 [macaddr] thing1[2407]: github.com/sirupsen/logrus.(*Logger).Errorf(0x85658120, 0x42b884, 0x44, 0x856d7ea8, 0x1, 0x1)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/sirupsen/logrus/logger.go:155 +0x64 fp=0x856d7dfc sp=0x856d7ddc pc=0x426f58
Apr 04 21:23:52 [macaddr] thing1[2407]: github.com/sirupsen/logrus.Errorf(0x42b884, 0x44, 0x856d7ea8, 0x1, 0x1)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/sirupsen/logrus/exported.go:142 +0x50 fp=0x856d7e18 sp=0x856d7dfc pc=0x4264b4
Apr 04 21:23:52 [macaddr] thing1[2407]: main.main()
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/b/cmd/thing1/main.go:79 +0x20c fp=0x856d7fc4 sp=0x856d7e18 pc=0x42a9c8
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.main()
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/proc.go:201 +0x2bc fp=0x856d7fe4 sp=0x856d7fc4 pc=0xb61482c0
Apr 04 21:23:52 [macaddr] thing1[2407]: runtime.goexit()
Apr 04 21:23:52 [macaddr] thing1[2407]:         /usr/lib/go/src/runtime/asm_arm.s:867 +0x4 fp=0x856d7fe4 sp=0x856d7fe4 pc=0xb6181240
Apr 04 21:23:52 [macaddr] thing1[2407]: goroutine 26 [select]:
Apr 04 21:23:52 [macaddr] thing1[2407]: github.com/papertrail/remote_syslog2/syslog.(*Logger).writeLoop(0x8548d320)
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/papertrail/remote_syslog2/syslog/syslog.go:216 +0xe8
Apr 04 21:23:52 [macaddr] thing1[2407]: created by github.com/papertrail/remote_syslog2/syslog.Dial
Apr 04 21:23:52 [macaddr] thing1[2407]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/papertrail/1.0-r5/build/src/github.com/papertrail/remote_syslog2/syslog/syslog.go:125 +0x204
Apr 04 21:23:52 [macaddr] systemd[1]: papertrail.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 04 21:23:52 [macaddr] systemd[1]: papertrail.service: Failed with result 'exit-code'.
Apr 04 21:23:55 [macaddr] thing2[2373]: fatal error: unexpected signal during runtime execution
Apr 04 21:23:55 [macaddr] thing2[2373]: [signal SIGSEGV: segmentation violation code=0x2 addr=0xb6a7f050 pc=0xb60d9274]
Apr 04 21:23:55 [macaddr] thing2[2373]: goroutine 1 [running]:
Apr 04 21:23:55 [macaddr] thing2[2373]: runtime.throw(0xb668d592, 0x2a)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/runtime/panic.go:608 +0x64 fp=0x852dd888 sp=0x852dd874 pc=0xb607b920
Apr 04 21:23:55 [macaddr] thing2[2373]: runtime.sigpanic()
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/runtime/signal_unix.go:374 +0x254 fp=0x852dd8ac sp=0x852dd888 pc=0xb6097e30
Apr 04 21:23:55 [macaddr] thing2[2373]: sync.(*Pool).Get(0x8500c080, 0xbf21bb02, 0x8544c120)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/sync/pool.go:130 +0x38 fp=0x852dd8d0 sp=0x852dd8b0 pc=0xb60d9274
Apr 04 21:23:55 [macaddr] thing2[2373]: github.com/sirupsen/logrus.Entry.log(0x8524e090, 0x8513d040, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/github.com/sirupsen/logrus/entry.go:101 +0x128 fp=0x852dd950 sp=0x852dd8d0 pc=0x5d8304
Apr 04 21:23:55 [macaddr] thing2[2373]: github.com/sirupsen/logrus.(*Entry).Error(0x8544c0f0, 0x852dd9b8, 0x1, 0x1)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/github.com/sirupsen/logrus/entry.go:156 +0x88 fp=0x852dd990 sp=0x852dd950 pc=0x5d8aac
Apr 04 21:23:55 [macaddr] thing2[2373]: github.com/sirupsen/logrus.(*Entry).Errorf(0x8544c0f0, 0x7db02a, 0x1c, 0x852ddad4, 0x3, 0x3)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/github.com/sirupsen/logrus/entry.go:204 +0xc0 fp=0x852dd9c0 sp=0x852dd990 pc=0x5d905c
Apr 04 21:23:55 [macaddr] thing2[2373]: github.com/sirupsen/logrus.(*Logger).Errorf(0x8524e090, 0x7db02a, 0x1c, 0x852ddad4, 0x3, 0x3)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/github.com/sirupsen/logrus/logger.go:155 +0x64 fp=0x852dd9e0 sp=0x852dd9c0 pc=0x5da598
Apr 04 21:23:55 [macaddr] thing2[2373]: github.com/sirupsen/logrus.Errorf(0x7db02a, 0x1c, 0x852ddad4, 0x3, 0x3)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/github.com/sirupsen/logrus/exported.go:142 +0x50 fp=0x852dd9fc sp=0x852dd9e0 pc=0x5d9a8c
Apr 04 21:23:55 [macaddr] thing2[2373]: b/hub/api/http.request(0x7d7539, 0x4, 0x851fa190, 0xe, 0x8a2710, 0x8546a1a0, 0x0, 0x0, 0x0, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/hub/api/http/httpclient.go:158 +0x5d8 fp=0x852ddb44 sp=0x852dd9fc pc=0x628664
Apr 04 21:23:55 [macaddr] thing2[2373]: b/hub/api/http.(*Client).CreateHub(0x8513d400, 0x851fc600, 0x11, 0x85460000, 0x1c3, 0x800, 0x8524fb90)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/hub/api/http/httpclient.go:54 +0x94 fp=0x852ddb80 sp=0x852ddb44 pc=0x6275fc
Apr 04 21:23:55 [macaddr] thing2[2373]: b/hub/api/mqtt.(*Client).createHub(0x8524cf00, 0x1a, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/hub/api/mqtt/mqtt.go:170 +0x5c fp=0x852ddbb0 sp=0x852ddb80 pc=0x682840
Apr 04 21:23:55 [macaddr] thing2[2373]: b/hub/api/mqtt.(*Client).connect(0x8524cf00, 0x0, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/hub/api/mqtt/mqtt.go:111 +0xd0 fp=0x852ddc20 sp=0x852ddbb0 pc=0x682088
Apr 04 21:23:55 [macaddr] thing2[2373]: b/hub/api/mqtt.(*Client).waitForConnection(0x8524cf00)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/hub/api/mqtt/mqtt.go:91 +0x60 fp=0x852ddc38 sp=0x852ddc20 pc=0x681f60
Apr 04 21:23:55 [macaddr] thing2[2373]: b/hub/api/mqtt.(*Client).Start(0x8524cf00)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/hub/api/mqtt/mqtt.go:85 +0x1c fp=0x852ddc40 sp=0x852ddc38 pc=0x681ef0
Apr 04 21:23:55 [macaddr] thing2[2373]: main.main()
Apr 04 21:23:55 [macaddr] thing2[2373]:         /src/firmware/machine-type-1/tmp/work/cortexa9hf-neon-poky-linux-gnueabi/hub/git-r3/build/src/b/cmd/hub/main.go:59 +0x118 fp=0x852ddfc4 sp=0x852ddc40 pc=0x7cf3dc
Apr 04 21:23:55 [macaddr] thing2[2373]: runtime.main()
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/runtime/proc.go:201 +0x2bc fp=0x852ddfe4 sp=0x852ddfc4 pc=0xb607e2c0
Apr 04 21:23:55 [macaddr] thing2[2373]: runtime.goexit()
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/runtime/asm_arm.s:867 +0x4 fp=0x852ddfe4 sp=0x852ddfe4 pc=0xb60b7240
Apr 04 21:23:55 [macaddr] thing2[2373]: goroutine 5 [syscall]:
Apr 04 21:23:55 [macaddr] thing2[2373]: os/signal.signal_recv(0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/runtime/sigqueue.go:139 +0x180
Apr 04 21:23:55 [macaddr] thing2[2373]: os/signal.loop()
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/os/signal/signal_unix.go:23 +0x14
Apr 04 21:23:55 [macaddr] thing2[2373]: created by os/signal.init.0
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/os/signal/signal_unix.go:29 +0x38
Apr 04 21:23:55 [macaddr] thing2[2373]: goroutine 20 [IO wait]:
Apr 04 21:23:55 [macaddr] thing2[2373]: internal/poll.runtime_pollWait(0xa513dfc0, 0x72, 0xb610d2c0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/runtime/netpoll.go:173 +0x44
Apr 04 21:23:55 [macaddr] thing2[2373]: internal/poll.(*pollDesc).wait(0x851f8424, 0x72, 0xffffff00, 0x8cb138, 0xb6e99700)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/internal/poll/fd_poll_runtime.go:85 +0x9c
Apr 04 21:23:55 [macaddr] thing2[2373]: internal/poll.(*pollDesc).waitRead(0x851f8424, 0x8530e000, 0x1000, 0x1000)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/internal/poll/fd_poll_runtime.go:90 +0x2c
Apr 04 21:23:55 [macaddr] thing2[2373]: internal/poll.(*FD).Read(0x851f8410, 0x8530e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/internal/poll/fd_unix.go:169 +0x15c
Apr 04 21:23:55 [macaddr] thing2[2373]: net.(*netFD).Read(0x851f8410, 0x8530e000, 0x1000, 0x1000, 0x0, 0x4, 0x851fc4e0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/fd_unix.go:202 +0x38
Apr 04 21:23:55 [macaddr] systemd[1]: thing2.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 04 21:23:55 [macaddr] thing2[2373]: net.(*conn).Read(0x85466030, 0x8530e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/net.go:177 +0x58
Apr 04 21:23:55 [macaddr] thing2[2373]: net/http.(*persistConn).Read(0x854620a0, 0x8530e000, 0x1000, 0x1000, 0x854620a0, 0x0, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/http/transport.go:1497 +0x17c
Apr 04 21:23:55 [macaddr] thing2[2373]: bufio.(*Reader).fill(0x8544c060)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/bufio/bufio.go:100 +0x10c
Apr 04 21:23:55 [macaddr] thing2[2373]: bufio.(*Reader).Peek(0x8544c060, 0x1, 0x2, 0x0, 0x0, 0x85448080, 0x0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/bufio/bufio.go:132 +0x2c
Apr 04 21:23:55 [macaddr] thing2[2373]: net/http.(*persistConn).readLoop(0x854620a0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/http/transport.go:1645 +0x1bc
Apr 04 21:23:55 [macaddr] thing2[2373]: created by net/http.(*Transport).dialConn
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/http/transport.go:1338 +0x980
Apr 04 21:23:55 [macaddr] thing2[2373]: goroutine 21 [select]:
Apr 04 21:23:55 [macaddr] thing2[2373]: net/http.(*persistConn).writeLoop(0x854620a0)
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/http/transport.go:1885 +0xd0
Apr 04 21:23:55 [macaddr] thing2[2373]: created by net/http.(*Transport).dialConn
Apr 04 21:23:55 [macaddr] thing2[2373]:         /usr/lib/go/src/net/http/transport.go:1339 +0x9a4

I don't have amd64 machine to test on (in fact we only have 1-2 arm type machines). I am planning to test it on my local env (OS X) but will have to figure out my build and how to run it with race detector. Will report back when I do.

@jasonkim
Copy link

jasonkim commented Apr 9, 2019

I wasn't able to repro on my OS X (with or without -race), but it's possible that I'm running it differently than how it's run in our deployed env.

@ianlancetaylor ianlancetaylor modified the milestones: Go1.12, Go1.13 Apr 10, 2019
@ianlancetaylor ianlancetaylor removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 10, 2019
@jasonkim
Copy link

There's some repro steps in the original ticket. It may help with debugging.

I can reproduce this now on an ARMv7 target, provided the image also includes the ca-certificates package.  Also, you have to wait until /dev/random has enough entropy.

I can also reproduce this natively by building go 1.10 from source, building a shared runtime with 'go install -linkshared -buildmode=shared std',  and doing a 'go get -linkshared github.com/gustavosbarreto/go-crazy'.  So it's not ARM-specific.

It's a panic due to a segfault, always appearing to happen around a sync.Pool request in logrus's Entry.log function.  However, it only seems to happen if the https request is also getting processed in other goroutines.  Panic tracebacks always point to the logrus package as the running thread, sometimes with and sometimes without other goroutines being active.

It does seem to happen only when the program is linked against shared runtime, not when linked statically.

Definitely an upstream issue, just not 100% sure that it's really in the Go runtime, or if logrus is misusing the sync package.

@andybons andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@kkoopa
Copy link

kkoopa commented Apr 8, 2020

The problem still exists under 1.13.8 under the same conditions.

fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0xcbff9c32 pc=0x75faf574]

goroutine 25 [running]:
runtime.throw(0x765f6426, 0x2a)
	/usr/lib/go/src/runtime/panic.go:774 +0x64 fp=0x45822c40 sp=0x45822c2c pc=0x75f43090
runtime.sigpanic()
	/usr/lib/go/src/runtime/signal_unix.go:378 +0x44c fp=0x45822c58 sp=0x45822c40 pc=0x75f607fc
sync.(*Pool).getSlow(0x4540ca40, 0x2, 0x0, 0x0)
	/usr/lib/go/src/sync/pool.go:174 +0x10c fp=0x45822c8c sp=0x45822c5c pc=0x75faf574
sync.(*Pool).Get(0x4540ca40, 0x3, 0x75f4efc4)
	/usr/lib/go/src/sync/pool.go:137 +0xe8 fp=0x45822cac sp=0x45822c8c pc=0x75faf424
github.com/Walkbase/spectre/lib/wifi.MACAddress.String(0x2, 0x100, 0x455e4000, 0x769cbe88)
	/opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/lib/wifi/mac_address.go:34 +0x28 fp=0x45822ce4 sp=0x45822cac pc=0x4ca028
github.com/Walkbase/spectre/lib/wifi.MACAddress.MarshalJSON(0x2, 0x100, 0x762a3848, 0x769cbe88, 0x4f85b8, 0x45474801, 0x4537b008)
	/opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/lib/wifi/mac_address.go:61 +0x24 fp=0x45822d04 sp=0x45822ce4 pc=0x4ca2f8
github.com/Walkbase/spectre/lib/wifi.(*MACAddress).MarshalJSON(0x4594a0a0, 0x4f85b8, 0x4594a0a0, 0x4537b008, 0x4594a0a0, 0x4594a001)
	<autogenerated>:1 +0x3c fp=0x45822d24 sp=0x45822d04 pc=0x4cafdc
encoding/json.marshalerEncoder(0x4566e720, 0x4f85b8, 0x4594a0a0, 0x8b, 0x100)
	/usr/lib/go/src/encoding/json/encode.go:453 +0xa8 fp=0x45822d60 sp=0x45822d24 pc=0x762a3868
encoding/json.structEncoder.encode(0x45826000, 0x6, 0x8, 0x456b66a0, 0x4566e720, 0x4f84a0, 0x4594a0a0, 0x99, 0x4f0100)
	/usr/lib/go/src/encoding/json/encode.go:664 +0x274 fp=0x45822dac sp=0x45822d60 pc=0x762a56f4
encoding/json.structEncoder.encode-fm(0x4566e720, 0x4f84a0, 0x4594a0a0, 0x99, 0x100)
	/usr/lib/go/src/encoding/json/encode.go:635 +0x64 fp=0x45822dd4 sp=0x45822dac pc=0x762b2874
encoding/json.(*encodeState).reflectValue(0x4566e720, 0x4f84a0, 0x4594a0a0, 0x99, 0x76ee0100)
	/usr/lib/go/src/encoding/json/encode.go:337 +0x68 fp=0x45822dec sp=0x45822dd4 pc=0x762a2e7c
encoding/json.(*encodeState).marshal(0x4566e720, 0x4f84a0, 0x4594a0a0, 0x45820100, 0x0, 0x0)
	/usr/lib/go/src/encoding/json/encode.go:309 +0x10c fp=0x45822e2c sp=0x45822dec pc=0x762a279c
encoding/json.Marshal(0x4f84a0, 0x4594a0a0, 0x4f84a0, 0x4594a0a0, 0x1, 0x25, 0x4faaf8)
	/usr/lib/go/src/encoding/json/encode.go:161 +0x40 fp=0x45822e64 sp=0x45822e2c pc=0x762a1ccc
main.(*receiver).start.func1(0x2, 0x100, 0x76a874d8, 0x4540cbc0, 0x456b0000, 0x45411080, 0x1, 0x1)
	/opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/exp/svc/moonraker/main.go:196 +0x17c fp=0x45822fcc sp=0x45822e64 pc=0x4e16e4
runtime.goexit()
	/usr/lib/go/src/runtime/asm_arm.s:868 +0x4 fp=0x45822fcc sp=0x45822fcc pc=0x75f8111c
created by main.(*receiver).start
	/opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/exp/svc/moonraker/main.go:181 +0xa4

1.14.1 also fails at the same location, but the stacktrace is less detailed and reports a panic instead of a fatal error

panic: interface conversion: interface {} is nil, not []uint8 [recovered]
        panic: interface conversion: interface {} is nil, not []uint8

goroutine 24 [running]:
encoding/json.(*encodeState).marshal.func1(0x4546be40)
        /usr/lib/go/src/encoding/json/encode.go:326 +0x9c
panic(0x769ba020, 0x45798020)
        /usr/lib/go/src/runtime/panic.go:967 +0x130
github.com/Walkbase/spectre/lib/wifi.MACAddress.String(0x2, 0x100, 0x455e4000, 0x769a8c80)
        /opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/lib/wifi/mac_address.go:34 +0x1c0
github.com/Walkbase/spectre/lib/wifi.MACAddress.MarshalJSON(0x2, 0x100, 0x763941c8, 0x769a8c80, 0x53e6d8, 0xa3585201, 0x65465fa8)
        /opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/lib/wifi/mac_address.go:61 +0x24
encoding/json.marshalerEncoder(0x4587c240, 0x53e6d8, 0x4565c050, 0x8b, 0x530100)
        /usr/lib/go/src/encoding/json/encode.go:477 +0x9c
encoding/json.condAddrEncoder.encode(0x76a42394, 0x76a42424, 0x4587c240, 0x53e6d8, 0x4565c050, 0x8b, 0x100)
        /usr/lib/go/src/encoding/json/encode.go:931 +0x90
encoding/json.structEncoder.encode(0x456be000, 0x6, 0x8, 0x45696680, 0x4587c240, 0x53e5c0, 0x4565c050, 0x99, 0x530100)
        /usr/lib/go/src/encoding/json/encode.go:758 +0x218
encoding/json.(*encodeState).reflectValue(0x4587c240, 0x53e5c0, 0x4565c050, 0x99, 0x45870100)
        /usr/lib/go/src/encoding/json/encode.go:358 +0x68
encoding/json.(*encodeState).marshal(0x4587c240, 0x53e5c0, 0x4565c050, 0x45460100, 0x0, 0x0)
        /usr/lib/go/src/encoding/json/encode.go:330 +0x10c
encoding/json.Marshal(0x53e5c0, 0x4565c050, 0x53e5c0, 0x4565c050, 0x1, 0x25, 0x5404e8)
        /usr/lib/go/src/encoding/json/encode.go:161 +0x40
main.(*receiver).start.func1(0x2, 0x100, 0x76a622b0, 0x4540cc00, 0x45690000, 0x45410fc8, 0x1, 0x1)
        /opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/exp/svc/moonraker/main.go:196 +0x17c
created by main.(*receiver).start
        /opt/yocto/tmp/work/cortexa7t2hf-neon-vfpv4-poky-linux-musleabi/spectre/1.0-AUTOINC+67d7b63028-r0/build/src/github.com/Walkbase/spectre/exp/svc/moonraker/main.go:181 +0xa4

@icholy
Copy link

icholy commented Jul 14, 2020

Is it possible to capture an rr recording? https://github.com/mozilla/rr

@seankhliao
Copy link
Member

Obsoleted by #47788

@golang golang locked and limited conversation to collaborators Oct 27, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests