groot: crash with SIGBUS signal

[bburghgr]

I've come across two different instances where some toy code crashes with a SIGBUS related error (once in the runtime, once in user code). I assume that both cases involve attempting to access a part of a memory mapped file which is out of bounds (or possible memory which is part of a file that is in the process of being Closed, in the second case). I suppose it's possible that the problem is actually in the go-mmap/mmap package, but I thought it best to report it here, in case this is a known issue (or has a known workaround) before I try to look into it any further.

For context: This happens in some proof-of-concept analysis code that I was using to compare/benchmark a go-hep workflow vs some existing analysis code. The workflow consists of a single goroutine looping over root files, opening 1 TTree in each file, and then doing some cuts / calculating some weights / filling some histograms. The input files are "local" (e.g. not over xrootd), although they are being accessed over a network (a symlink on an afs volume that points to an eos-accessible file on grid space, all running on lxplus). I don't think the network access should matter, although it may make it easier to trigger the error (in case e.g. network latency makes it easier for a race to occur).

Case 1, where it happens in user code while reading from a TTree:

unexpected fault address 0x88a699
unexpected fault address 0x433a20
fatal error: fault
[signal SIGBUS: bus error code=0x2 addr=0x433a20 pc=0x433a20]

goroutine 1 [running]:
runtime.throw({0x976958, 0x1})
        /usr/local/go/src/runtime/panic.go:1198 +0x71 fp=0xc00032b7c8 sp=0xc00032b798 pc=0x433a91
runtime.sigpanic()
        /usr/local/go/src/runtime/signal_unix.go:732 +0x125 fp=0xc00032b818 sp=0xc00032b7c8 pc=0x448c65
runtime.throw({0x97f943, 0xc00032b868})
        /usr/local/go/src/runtime/panic.go:1188 fp=0xc00032b820 sp=0xc00032b818 pc=0x433a20
runtime.sigpanic()
        /usr/local/go/src/runtime/signal_unix.go:732 +0x125 fp=0xc00032b870 sp=0xc00032b820 pc=0x448c65
go-hep.org/x/hep/groot/rtree.(*tbranch).UnmarshalROOT(0x904620, 0xc000514030)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/rtree/branch.go:355 +0x1af9 fp=0xc00032b878 sp=0xc00032b870 pc=0x88a699
go-hep.org/x/hep/groot/rbytes.(*RBuffer).ReadObjectAny(0xc000882050)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/rbytes/rbuffer.go:692 +0x30f fp=0xc00032b968 sp=0xc00032b878 pc=0x4f8ccf
go-hep.org/x/hep/groot/rcont.(*ObjArray).UnmarshalROOT(0xc00032baf0, 0xc000882050)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/rcont/objarray.go:127 +0x1fb fp=0xc00032b9c8 sp=0xc00032b968 pc=0x63e07b
go-hep.org/x/hep/groot/rtree.(*ttree).UnmarshalROOT(0xc005538000, 0xc000882050)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/rtree/tree.go:410 +0x886 fp=0xc00032bbc0 sp=0xc00032b9c8 pc=0x8ab826
go-hep.org/x/hep/groot/riofs.(*Key).Object(0xc005f88320)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/riofs/key.go:370 +0x245 fp=0xc00032bca8 sp=0xc00032bbc0 pc=0x6abe45
go-hep.org/x/hep/groot/riofs.(*tdirectoryFile).Get(0xc000e0d498, {0x97711b, 0x7})
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/riofs/dir.go:395 +0x2f8 fp=0xc00032bd90 sp=0xc00032bca8 pc=0x6a1bb8
go-hep.org/x/hep/groot/riofs.(*File).Get(...)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/riofs/file.go:859
main.processFile({0xc00040c1e0, 0xe1})
        /home/blake/Documents/hptaunu/go-stuff/go-analysis-framework/cmd/framework-test/main.go:55 +0xac fp=0xc00032bf10 sp=0xc00032bd90 pc=0x8c0c2c
main.main()
        /home/blake/Documents/hptaunu/go-stuff/go-analysis-framework/cmd/framework-test/main.go:41 +0x1cf fp=0xc00032bf80 sp=0xc00032bf10 pc=0x8c0b2f
runtime.main()
        /usr/local/go/src/runtime/proc.go:255 +0x227 fp=0xc00032bfe0 sp=0xc00032bf80 pc=0x436167
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc00032bfe8 sp=0xc00032bfe0 pc=0x4627e1

Case 2, where it happens in the runtime (gc) while user code is (apparently) in the process of closing a file:

fatal error: unexpected signal during runtime execution
[signal SIGBUS: bus error code=0x2 addr=0xb32060 pc=0x44d27f]

runtime stack:
runtime.throw({0x98b056, 0x450e30})   
        /usr/local/go/src/runtime/panic.go:1198 +0x71
runtime.sigpanic()
        /usr/local/go/src/runtime/signal_unix.go:719 +0x396
runtime.getStackMap(0xc000833be8, 0xc0008338d0, 0xcd)
        /usr/local/go/src/runtime/stack.go:1332 +0x41f
runtime.scanframeworker(0xc000833be8, 0xc000833cc8, 0xdeb7e0)
        /usr/local/go/src/runtime/mgcmark.go:912 +0x7e
runtime.scanstack.func1(0xd8a7f8, 0xdeb7e0)
        /usr/local/go/src/runtime/mgcmark.go:745 +0x25
runtime.gentraceback(0x43b15b, 0xc000833cb0, 0x80c00392ffff, 0x203000e, 0x0, 0x0, 0x7fffffff, 0xc000833e28, 0x0, 0x0)
        /usr/local/go/src/runtime/traceback.go:350 +0xac3
runtime.scanstack(0xc0000001a0, 0xc000057698)
        /usr/local/go/src/runtime/mgcmark.go:748 +0x197
runtime.markroot.func1()
        /usr/local/go/src/runtime/mgcmark.go:232 +0xb1
runtime.markroot(0xc000057698, 0x24)
        /usr/local/go/src/runtime/mgcmark.go:205 +0x170
runtime.gcDrain(0xc000057698, 0x3)
        /usr/local/go/src/runtime/mgcmark.go:1013 +0x379
runtime.gcBgMarkWorker.func2()
        /usr/local/go/src/runtime/mgc.go:1269 +0xa5
runtime.systemstack()
        /usr/local/go/src/runtime/asm_amd64.s:383 +0x49

goroutine 6 [GC worker (idle)]:
runtime.systemstack_switch()
        /usr/local/go/src/runtime/asm_amd64.s:350 fp=0xc00007a760 sp=0xc00007a758 pc=0x460700
runtime.gcBgMarkWorker()
        /usr/local/go/src/runtime/mgc.go:1256 +0x1b1 fp=0xc00007a7e0 sp=0xc00007a760 pc=0x41af71
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc00007a7e8 sp=0xc00007a7e0 pc=0x4627e1
created by runtime.gcBgMarkStartWorkers
        /usr/local/go/src/runtime/mgc.go:1124 +0x25

goroutine 1 [syscall (scan)]:
syscall.Syscall(0xb, 0x7fcd7a4c4000, 0x113c871ed, 0x0)
        /usr/local/go/src/syscall/asm_linux_amd64.s:20 +0x5
golang.org/x/sys/unix.munmap(0x956100, 0x42e6ec)
        /home/blake/go/pkg/mod/golang.org/x/sys@v0.0.0-20210927094055-39ccf1dd6fa6/unix/zsyscall_linux.go:1747 +0x38
golang.org/x/sys/unix.(*mmapper).Munmap(0xdfd460, {0x7fcd7a4c4000, 0x0, 0x0})
        /home/blake/go/pkg/mod/golang.org/x/sys@v0.0.0-20210927094055-39ccf1dd6fa6/unix/syscall_unix.go:149 +0x12f
golang.org/x/sys/unix.Munmap(...)
        /home/blake/go/pkg/mod/golang.org/x/sys@v0.0.0-20210927094055-39ccf1dd6fa6/unix/syscall_linux.go:2103
github.com/go-mmap/mmap.(*File).Close(0x8963c5)
        /home/blake/go/pkg/mod/github.com/go-mmap/mmap@v0.6.0/mmap_unix.go:77 +0xc9
go-hep.org/x/hep/groot/riofs.(*File).Close(0xc0000fc000)
        /home/blake/Documents/hptaunu/go-stuff/hep/groot/riofs/file.go:469 +0x15d
main.processFile({0xc00046c460, 0xd4})
        /home/blake/Documents/hptaunu/go-stuff/go-analysis-framework/cmd/framework-test/main.go:112 +0x542
main.main()
        /home/blake/Documents/hptaunu/go-stuff/go-analysis-framework/cmd/framework-test/main.go:41 +0x1cf

[sbinet]

thanks for the report.
I am still on holidays so I won't look into it before next week.

but back in the days, I had a similar report about segfaults+SIGBUS in ATLAS' Athena framework.
it was coming from AFS sweeping .so from under the feet of a running Athena application.
this looks eerily similar.
(well, the 2nd looks indeed more like a race in go-mmap or groot)

it would be great to have a reproducer I could play with when back from vacations :)

[bburghgr]

Some quick followup from my side: I haven't managed to create a reproducer that consistently triggers a SIGBUS, but I'm reasonably confident that this is not only a go-hep issue. I was able to crash things a couple of times by using filesystem.Glob to read the contents of some directories on eos. However, in all cases where I have gotten a SIGBUS, the application binary has been on AFS, so I think there is a more general Go+AFS issue. Moving the application binary to eos or /tmp (or really anywhere off of AFS) seems to work well as a workaround. I don't have enough spare AFS space at the moment to copy any test root files there, but I wouldn't be too surprised if things also crash in that scenario.

I did notice that an upstream Go issue (about a SIGBUS in the linker) has a comment about a similar crash when building go packages on AFS: golang/go#37310 (comment). That user still saw problems when building packges in /tmp, but if the main go binary was stored on AFS, then that would be consistent with what I'm seeing in my tests.

[sbinet]

hi @vkuznet

did you get something in the end wrt your SIGBUS + AFS issue from golang/go#37310 (comment) ?
(I couldn't find a follow up issue)

@bburghgr: I couldn't find the old bug report I was alluding to above.
it was before the migration from Savanna to JIRA, and I am not sure all were migrated to JIRA.
but I vaguely remember it was b/c the binary (ie: .exe and .so) was replaced by the new iteration of nightlies (this was ocurring when the tests for nighlty N had its binaries being (partly) replaced by the artifacts from nightly N+1) as explained (for NFS) here:

• https://rachelbythebay.com/w/2018/03/15/core/

here are a few leads for SIGBUS origins:

• https://stackoverflow.com/questions/2089167/debugging-sigbus-on-x86-linux

anyways.
in order to weed out the mmap issue, could you try the issue-885 branch from:

• https://github.com/sbinet-hep/hep/tree/issue-885 ?
  (you might experience a serious drop in performances wrt groot+mmap)

[bburghgr]

Hi @sbinet,

Two things to report:

1. I still see a crash using the issue-885 branch.
2. I am able to reproduce something approximating @vkuznet's crash with a simple go install go-hep.org/x/hep/groot/cmd/root-dump@master, if the go installation (1.17.6) is on AFS. I have not been able to reproduce this with a go installation (including the main go binary) on /tmp or similar. Even trying to go run a "hello world" was sufficient to trigger it on my first attempt, though subsequent attempts have been successful (even after clearing the build cache).

So at this point, I'm reasonably confident that this is a Go+AFS problem, not a go-hep problem.

[bburghgr]

Hi again @sbinet,

A third thing to report: Doing some more digging, a remarkably similar error happens with go binaries accessed over gcsfuse: golang/go#48997. GODEBUG=asyncpreemptoff=1 seems to prevent the crash in that case, and it looks like it works here as well (at least in my initial tests, some things are still running).

[sbinet]

did you try with running your analysis executable out of AFS? (and compiled against the issue-885 branch)

when you mention GODEBUG=asyncpreemptoff=1 preventing the crash, on which setup does this applies?

anyways... I guess this will probably warrant a bona fide golang/go issue.

[bburghgr]

My analysis code was able to run OK when the binary was on /eos. Compiled using the issue-885, it still crashes on AFS (and I did not attempt to run it again from /eos or elsewhere, since that would take a while -- it did seem to be slower than the mmaped version).

GODEBUG=asyncpreemptoff=1 seemed to work with go install / go build / go run commands. I'm re-running my analysis code (from AFS, compiled against go-hep/hep@main) right now, to see disabling preempt is enough. If not, I'll retry with the issue-885 branch (but I would be kind of surprised if there are two independent problems causing a SIGBUS).

[vkuznet]

@sbinet I didn't get anything back from Go team and I have't had time to work on this by myself.

[bburghgr]

One last update (for now) from my side. Running my analysis code (built against go-hep/hep@main, not the issue-885 branch) works on AFS if I run with the GODEBUG=asyncpreemptoff=1 option.

At this point, I'm fairly well convinced that this problem isn't go-hep related at all, except to the extent that my analysis code is pretty I/O heavy (which seems to be the easiest way to trigger the crash). I will go ahead an open an issue with golang/go.

[sbinet]

ok, thanks for your investigation work.

BTW, I'd be interested in your conclusions wrt the performances of your analysis framework.
either privately or on the Go-HEP mailing list:

• mailto:~sbinet/go-hep@lists.sr.ht
• https://lists.sr.ht/~sbinet/go-hep (its web interface)

so far, the performance numbers gathered and advertised on the ROOT forum:

• https://root-forum.cern.ch/t/gohep-groot-v0-27-0-root-split-groot-faster-than-root/39609

have been confirmed by my synthetic benchmarks, by @rmadar's analysis framework and (implicitly) by the ROOT guys (as they didn't disagree with the assessment).
it would be very interesting to have another 3rd party to add to the mix.

(also, it would be great to add your framework and/or tools to Go-HEP's "hall of fame" go-hep.org/users, if possible.)