lidavidm commented on issue #729: URL: https://github.com/apache/arrow-adbc/issues/729#issuecomment-1634673227
# `runtime: pointer 0xc000376000 to unused region of span span.base()=0xc0001e4000 span.limit=0xc0001e5fe0 span.state=1` TL;DR: an uninitialized C Data Interface struct may happen to contain a pointer that looks like a Go pointer. If the Go garbage collector sees this, it'll get confused and will panic: > Note: the current implementation has a bug. While Go code is permitted to write nil or a C pointer (but not a Go pointer) to C memory, the current implementation may sometimes cause a runtime error if the contents of the C memory appear to be a Go pointer. Therefore, avoid passing uninitialized C memory to Go code if the Go code is going to store pointer values in it. Zero out the memory in C before passing it to Go. (https://pkg.go.dev/cmd/cgo) This is _very annoying_ to debug. ## Background The ADBC Flight SQL driver (and the Snowflake) driver are unusual in that they are implemented in Go, then wrapped in a C API and exposed to Python and other languages. [Testing concurrent usage of the Flight SQL driver](https://github.com/apache/arrow-adbc/issues/729) turned up a crash that would take down the entire process. The error message varied, but was generally looked like one of these two: ``` runtime: marked free object in span 0x7f7bc8480ba8, elemsize=24 freeindex=0 (bad use of unsafe.Pointer? try -d=checkptr) runtime: pointer 0xc000376000 to unused region of span span.base()=0xc0001e4000 span.limit=0xc0001e5fe0 span.state=1 ``` This almost certainly means we're violating the rules of how to use CGO and/or `unsafe` properly. But where and how are we doing so? All we seem to know is the address of an invalid pointer, not where it came from… ## The Easy Suspects: `GODEBUG=cgocheck=2` and `-d=checkptr` As suggested, we can compile with the flag `-d=checkptr`. This adds [a number of checks](https://go.dev/src/runtime/checkptr.go) that we're following the rules of how to use [`unsafe.Pointer`](https://pkg.go.dev/unsafe#Pointer). We can also use `GODEBUG=cgocheck=2`, which adds checks that we're using CGO correctly. Unfortunately, neither turned up anything useful. ## Reading the Clues This problem only reproduced with pyarrow 10.0.1 from conda-forge. Curiously, even a locally-built pyarrow of the same version wouldn't fail. But otherwise, with the given script in the original issue, it crashed reliably. I decided to focus on this case: ``` runtime: pointer 0xc0002ff000 to unallocated span span.base()=0xc0002fe000 span.limit=0xc000306000 span.state=0 fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?) runtime stack: runtime.throw({0x7f8e5906f5c2?, 0x7f8e250f9388?}) /usr/local/go/src/runtime/panic.go:1047 +0x5f fp=0x7f8e250f9370 sp=0x7f8e250f9340 pc=0x7f8e59195a7f runtime.badPointer(0x7f8e60057b40, 0xc000204820?, 0x0, 0x7f8e59850e16?) /usr/local/go/src/runtime/mbitmap.go:314 +0x150 fp=0x7f8e250f93c0 sp=0x7f8e250f9370 pc=0x7f8e59174ef0 runtime.findObject(0xc000070cc0?, 0xc000070c88?, 0x7f8e591c7361?) /usr/local/go/src/runtime/mbitmap.go:357 +0xa6 fp=0x7f8e250f93f8 sp=0x7f8e250f93c0 pc=0x7f8e59175086 runtime.wbBufFlush1(0xc00004e000) /usr/local/go/src/runtime/mwbbuf.go:260 +0xe5 fp=0x7f8e250f9440 sp=0x7f8e250f93f8 pc=0x7f8e59190a25 runtime.wbBufFlush.func1() /usr/local/go/src/runtime/mwbbuf.go:201 +0x25 fp=0x7f8e250f9458 sp=0x7f8e250f9440 pc=0x7f8e591c0085 runtime.systemstack() /usr/local/go/src/runtime/asm_amd64.s:496 +0x46 fp=0x7f8e250f9460 sp=0x7f8e250f9458 pc=0x7f8e591c5486 goroutine 18 [running, locked to thread]: runtime.systemstack_switch() /usr/local/go/src/runtime/asm_amd64.s:463 fp=0xc000070598 sp=0xc000070590 pc=0x7f8e591c5420 runtime.wbBufFlush(0x7f8e591753ba?, 0xc000070650?) /usr/local/go/src/runtime/mwbbuf.go:200 +0x6c fp=0xc0000705b8 sp=0xc000070598 pc=0x7f8e591908ec runtime.wbBufFlush(0xc0000145f8, 0x0) <autogenerated>:1 +0x2c fp=0xc0000705d8 sp=0xc0000705b8 pc=0x7f8e591c9e6c runtime.gcWriteBarrier() /usr/local/go/src/runtime/asm_amd64.s:1696 +0xa3 fp=0xc000070658 sp=0xc0000705d8 pc=0x7f8e591c77a3 runtime.gcWriteBarrierSI() /usr/local/go/src/runtime/asm_amd64.s:1748 +0x7 fp=0xc000070660 sp=0xc000070658 pc=0x7f8e591c7867 google.golang.org/grpc.newClientStream({0x7f8e599bf738, 0xc0002e7da0}, 0x7f8e59e8f020, 0xc0000a1880, {0x7f8e59066f52, 0x2d}, {0xc0002e7ce0, 0x3, 0x3}) /home/lidavidm/go/pkg/mod/google.golang.org/[email protected]/stream.go:223 +0x585 fp=0xc0000707b0 sp=0xc000070660 pc=0x7f8e597773c5 ``` Reading through the Go sources in that trace, what's happening here is that we're trying to write a pointer value while the garbage collector is running. We know that because of the call to `runtime.gcWriteBarrier`. Go's GC is concurrent, so writes have to cooperate with the GC so that it doesn't accidentally miss something. When writing a pointer value to the heap, instead of directly writing the new value to memory, Go first calls out to a *write barrier*. Roughly speaking (as someone who's not a compiler/languages developer), this means that we first tell the garbage collector about (1) the pointer we're about to write and (2) the pointer we're about to *overwrite*, before actually writing the value. From [`mbarrier.go`](https://go.dev/src/runtime/mbarrier.go): ```go // 1. shade(*slot) prevents a mutator from hiding an object by moving // the sole pointer to it from the heap to its stack. If it attempts // to unlink an object from the heap, this will shade it. // // 2. shade(ptr) prevents a mutator from hiding an object by moving // the sole pointer to it from its stack into a black object in the // heap. If it attempts to install the pointer into a black object, // this will shade it. ``` Go's compiler implements this by emitting a call to a function, `runtime.gcWriteBarrier`, each time we want to write a pointer value to memory. The function stores the two pointers in a *write barrier buffer* for the GC to follow up on later, then does the actual write. From [`mwbbuf.go`](https://go.dev/src/runtime/mwbbuf.go): ```go // wbBuf is a per-P buffer of pointers queued by the write barrier. // This buffer is flushed to the GC workbufs when it fills up and on // various GC transitions. // // This is closely related to a "sequential store buffer" (SSB), // except that SSBs are usually used for maintaining remembered sets, // while this is used for marking. type wbBuf struct { // next points to the next slot in buf. It must not be a // pointer type because it can point past the end of buf and // must be updated without write barriers. // // This is a pointer rather than an index to optimize the // write barrier assembly. next uintptr // end points to just past the end of buf. It must not be a // pointer type because it points past the end of buf and must // be updated without write barriers. end uintptr // buf stores a series of pointers to execute write barriers // on. This must be a multiple of wbBufEntryPointers because // the write barrier only checks for overflow once per entry. buf [wbBufEntryPointers * wbBufEntries]uintptr } const ( // wbBufEntries is the number of write barriers between // flushes of the write barrier buffer. // // This trades latency for throughput amortization. Higher // values amortize flushing overhead more, but increase the // latency of flushing. Higher values also increase the cache // footprint of the buffer. // // TODO: What is the latency cost of this? Tune this value. wbBufEntries = 256 // wbBufEntryPointers is the number of pointers added to the // buffer by each write barrier. wbBufEntryPointers = 2 ) ``` If the buffer is full, it first jumps to the GC to check all the pointers before continuing. Going back to the stack trace above, we're in this case, as we can see because `gcWriteBarrier` has jumped to `wbBufFlush`. And the GC is unhappy, because one of those pointers—`0xc0002ff000`—is invalid. We can confirm this by searching for the two pointers we know must exist in the Go heap. We know that the Go heap is always at a fixed address, `0xc000000000`. From [`runtime/malloc.go`](https://go.dev/src/runtime/malloc.go): ```go // Starting at 0x00c0 means that the valid memory addresses // will begin 0x00c0, 0x00c1, ... // In little-endian, that's c0 00, c1 00, ... None of those are valid // UTF-8 sequences, and they are otherwise as far away from // ff (likely a common byte) as possible. If that fails, we try other 0xXXc0 // addresses. An earlier attempt to use 0x11f8 caused out of memory errors ``` We can see this in the debugger: ``` (rr) info proc map process 1446086 Mapped address spaces: Start Addr End Addr Size Offset objfile 0x68000000 0x68200000 0x200000 0x0 0x6fffd000 0x70001000 0x4000 0x0 /usr/lib/rr/librrpage.so 0x70001000 0x70002000 0x1000 0x0 /tmp/rr-shared-preload_thread_locals-1446204-0 0x70003000 0x70004000 0x1000 0x0 0xc000000000 0xc000400000 0x400000 0x0 0xc000400000 0xc004000000 0x3c00000 0x0 0x55c71b4c1000 0x55c71b5b1000 0xf0000 0x0 /home/lidavidm/miniforge3/envs/arrow-bad/bin/python3.11 ``` We can use the debugger to search for the offending address in the heap, which *should* be the write buffer barrier: ``` (rr) find /g 0xc000000000,0xc004000000,0xc0002ff000 0xc00004fd18 0xc000305000 2 patterns found. ``` Which one is correct? It should be the first one. Going back to the stack trace: ``` runtime.wbBufFlush1(0xc00004e000) ``` The implementation takes the address of a large structure that contains the write barrier buffer. And from the Go code above, the buffer is 512 entries. The first address is relatively close to the address in the stack trace. The contents of memory look reasonable, too: ``` (rr) x/4xg 0xc00004fd10 0xc00004fd10: 0x00007f8e0c000d20 0x000000c0002ff000 0xc00004fd20: 0x000000c00003e580 0x0000000000000000 ``` That's indeed a pair of pointers, one of which is on the C heap and one of which is the offending Go pointer. ## Tracking the Culprit You may have noticed we're using `rr` and not `gdb` to debug. [`rr`](https://rr-project.org/) is like `gdb`, but supports time-travel debugging—you can start from where your program crashed, set breakpoints and such, *and run it backwards*. Here, we'll use it to figure out who wrote this bad pointer to the write barrier buffer. ``` (rr) watch *0xc00004fd18 Hardware watchpoint 1: *0xc00004fd18 (rr) reverse-cont Continuing. Thread 2 received signal SIGABRT, Aborted. 0x0000000070000002 in syscall_traced () (rr) reverse-cont Continuing. Thread 2 hit Hardware watchpoint 1: *0xc00004fd18 Old value = 3141632 New value = 0 runtime.gcWriteBarrier () at /usr/local/go/src/runtime/asm_amd64.s:1655 1655 MOVQ R13, -8(R12) // Record *slot ``` We set a watchpoint on the address containing our bad pointer. Then we step the program backwards a couple times…to find the write barrier! And from the handily commented source, we know that we're recording a pointer that *we're about to overwrite*. We also get a nice backtrace: ``` (rr) bt #0 runtime.gcWriteBarrier () at /usr/local/go/src/runtime/asm_amd64.s:1655 #1 0x00007f8e5984092d in github.com/apache/arrow/go/v13/arrow/cdata.(*schemaExporter).finish (exp=0xc000070bf0, out=0x7f8e250f9480) at /home/lidavidm/Code/upstream/adbc/arrow-go/go/arrow/cdata/cdata_exports.go:338 #2 0x00007f8e59840c98 in github.com/apache/arrow/go/v13/arrow/cdata.exportField (field=..., out=0x7f8e250f9480) at /home/lidavidm/Code/upstream/adbc/arrow-go/go/arrow/cdata/cdata_exports.go:363 #3 0x00007f8e5983683d in github.com/apache/arrow/go/v13/arrow/cdata.ExportArrowSchema (schema=0xc0002783c0, out=0x7f8e250f9480) at /home/lidavidm/Code/upstream/adbc/arrow-go/go/arrow/cdata/interface.go:203 #4 0x00007f8e598418af in github.com/apache/arrow/go/v13/arrow/cdata.cRecordReader.getSchema (rr=..., out=0x7f8e250f9480, ~r0=<optimized out>) at /home/lidavidm/Code/upstream/adbc/arrow-go/go/arrow/cdata/cdata_exports.go:458 #5 0x00007f8e59842b8d in github.com/apache/arrow/go/v13/arrow/cdata.streamGetSchema (handle=<optimized out>, out=0x7f8e250f9480, ~r0=<optimized out>) at /home/lidavidm/Code/upstream/adbc/arrow-go/go/arrow/cdata/exports.go:129 ``` The line numbers are off since (as part of many hours of debugging that I am omitting here) the code is modified, but here's the offending segment: ```go cName := C.CString(exp.name) cFormat := C.CString(exp.format) out.name = cName out.format = cFormat ``` We're just storing a C-allocated pointer into C-allocated memory, following the CGO rules…so where did the Go pointer come from? ``` (rr) f 1 #1 0x00007f8e5984092d in github.com/apache/arrow/go/v13/arrow/cdata.(*schemaExporter).finish (exp=0xc000070bf0, out=0x7f8e250f9480) at /home/lidavidm/Code/upstream/adbc/arrow-go/go/arrow/cdata/cdata_exports.go:338 338 out.format = cFormat (rr) p out $1 = (github.com/apache/arrow/go/v13/arrow/cdata._Ctype_struct_ArrowSchema *) 0x7f8e250f9480 (rr) p *out $2 = {format = 0xc0002ff000 "", name = 0x7f8e0c001c90 "", metadata = 0x7f8e0c001b50 "\250\324\307f\216\177", flags = 140249363978005, n_children = 140249363923072, children = 0x0, dictionary = 0x0, release = 0x7f8e59851479 <_cgo_release_context+21>, private_data = 0x7f8e250f9630} ``` Hmm, it seems our C-allocated struct already had a Go pointer inside it (as we can see from the address beginning in `0xc00…`). If you've written a lot of C/C++, alarm bells might be ringing, but let's follow things through to their conclusion. ## Capturing the Culprit We can set another watchpoint and run in reverse again, to find out who wrote `0xc0002ff000` to `0x7f8e250f9480`. ``` (rr) reverse-cont Continuing. [Switching to Thread 1446086.1446098] Thread 2 hit Hardware watchpoint 2: *0x7f8e250f9480 Old value = 3141632 New value = 0 0x00007f8e591ae7e8 in runtime.copystack (gp=0xc000204820, newsize=<optimized out>) at /usr/local/go/src/runtime/stack.go:885 885 adjinfo.old = old (rr) si Thread 2 hit Hardware watchpoint 2: *0x7f8e250f9480 Old value = 0 New value = 3141632 runtime.copystack (gp=0xc000204820, newsize=<optimized out>) at /usr/local/go/src/runtime/stack.go:886 886 adjinfo.delta = new.hi - old.hi (rr) x/2xg 0x7f8e250f9480 0x7f8e250f9480: 0x000000c0002ff000 0x0000000000000000 (rr) bt #0 runtime.copystack (gp=0xc000204820, newsize=<optimized out>) at /usr/local/go/src/runtime/stack.go:886 #1 0x00007f8e591aef37 in runtime.newstack () at /usr/local/go/src/runtime/stack.go:1114 #2 0x00007f8e591c5540 in runtime.morestack () at /usr/local/go/src/runtime/asm_amd64.s:574 #3 0x00007f8e250f9758 in ?? () #4 0x00007f8e6101e2c0 in ?? () #5 0x0000000000000000 in ?? () ``` Well, there's our value. What's going on here? It's not really important what this code does exactly, but we're in some Go runtime code that expands stacks (since goroutine stacks are dynamically allocated), and this runtime code is using the C stack. As part of that, it appears to have stored a value that happens to look like a Go pointer into the C stack. We can see the stack pointer is quite close to our C Data Interface struct's address above: ``` (rr) p/x $rsp $6 = 0x7f8e250f93f0 ``` Did we allocate our `ArrowSchema` on the stack? Well, yes. Our reproducer uses pyarrow, and pyarrow builds on top of libarrow, which in version 10.0.1 would import schemas like so: ```cpp std::shared_ptr<Schema> CacheSchema() const { if (!schema_) { struct ArrowSchema c_schema; ARROW_CHECK_OK(StatusFromCError(stream_.get_schema(&stream_, &c_schema))); schema_ = ImportSchema(&c_schema).ValueOrDie(); } return schema_; } ``` We stack-allocate _and do not zero-initialize_ an `ArrowSchema`. Normally, this is fine; the code producing the schema is supposed to just blindly overwrite the existing value because it shouldn't matter. But there's this little note in the CGO documentation: > Note: the current implementation has a bug. While Go code is permitted to write nil or a C pointer (but not a Go pointer) to C memory, the current implementation may sometimes cause a runtime error if the contents of the C memory appear to be a Go pointer. Therefore, avoid passing uninitialized C memory to Go code if the Go code is going to store pointer values in it. Zero out the memory in C before passing it to Go. (https://pkg.go.dev/cmd/cgo) What's the "bug"? Well, let's go back to the write buffer barrier. It's in assembly, but well commented and pretty straightforward: ```asm // gcWriteBarrier performs a heap pointer write and informs the GC. // // gcWriteBarrier does NOT follow the Go ABI. It takes two arguments: // - DI is the destination of the write // - AX is the value being written at DI // It clobbers FLAGS. It does not clobber any general-purpose registers, // but may clobber others (e.g., SSE registers). // Defined as ABIInternal since it does not use the stack-based Go ABI. TEXT runtime·gcWriteBarrier<ABIInternal>(SB),NOSPLIT,$112 // Save the registers clobbered by the fast path. This is slightly // faster than having the caller spill these. MOVQ R12, 96(SP) MOVQ R13, 104(SP) // TODO: Consider passing g.m.p in as an argument so they can be shared // across a sequence of write barriers. MOVQ g_m(R14), R13 MOVQ m_p(R13), R13 MOVQ (p_wbBuf+wbBuf_next)(R13), R12 // Increment wbBuf.next position. LEAQ 16(R12), R12 MOVQ R12, (p_wbBuf+wbBuf_next)(R13) CMPQ R12, (p_wbBuf+wbBuf_end)(R13) // Record the write. MOVQ AX, -16(R12) // Record value // Note: This turns bad pointer writes into bad // pointer reads, which could be confusing. We could avoid // reading from obviously bad pointers, which would // take care of the vast majority of these. We could // patch this up in the signal handler, or use XCHG to // combine the read and the write. MOVQ (DI), R13 MOVQ R13, -8(R12) // Record *slot // Is the buffer full? (flags set in CMPQ above) JEQ flush ret: MOVQ 96(SP), R12 MOVQ 104(SP), R13 // Do the write. MOVQ AX, (DI) RET ``` As we can see, it just stores two pointers, as advertised—the pointer we're trying to write, *and the pointer we're overwriting*. It doesn't differentiate between Go and C allocated memory. So if the C allocated memory *happens* to have something that looks like a Go pointer, and we apply this barrier to it…the GC gets very confused, because we've just pulled an invalid pointer from thin air. ## The Solution Now that we know what happened, we just have to somehow clear the struct before it hits Go. That's implemented here: https://github.com/apache/arrow/pull/36670, along with some incidental fixes for things that were found as part of the testing. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
