python/adbc_driver_flightsql: crash in concurrent usage

[lidavidm]

$ go run github.com/apache/arrow/go/v12/arrow/flight/flightsql/example/cmd/sqlite_flightsql_server@latest -port 12345

Separately:

$ python -m venv venv
$ source venv/bin/activate
$ pip install pyarrow==10.0.1 adbc-driver-flightsql

Then run this script:

import concurrent.futures
from concurrent.futures import ThreadPoolExecutor
import adbc_driver_flightsql.dbapi
import pyarrow


def task(conn):
    with conn.cursor() as cur:
        cur.execute("SELECT 1")
        cur.fetch_arrow_table()


with adbc_driver_flightsql.dbapi.connect("grpc://localhost:12345") as conn:
    with ThreadPoolExecutor() as ex:
        while True:
            futures = [ex.submit(task, conn) for _ in range(23)]
            for future in concurrent.futures.as_completed(futures):
                future.result()

The Go runtime should immediately crash:

runtime: marked free object in span 0x7f7bc8480ba8, elemsize=24 freeindex=0 (bad use of unsafe.Pointer? try -d=checkptr)

Technically, the concurrent conn.cursor() call here is not allowed. But the crash seems to be unrelated to that; the crash won't occur if you comment out fetch_arrow_table or replace it with fetchone.

It also won't happen if you have PyArrow 11, so it may be a regression in PyArrow and not something we should be concerned about.

[lidavidm]

I think I've observed a crash like this without concurrent usage. @zeroshade should we perhaps just enable checkptr in our releases? It has a performance cost but I don't think users will be spamming calls spanning the FFI boundary.

Specifically, -d=checkptr checks the following:

1. When converting unsafe.Pointer to *T, the resulting pointer must be aligned appropriately for T.
2. If the result of pointer arithmetic points into a Go heap object, one of the unsafe.Pointer-typed operands must point into the same object.

https://go.dev/doc/go1.14

It sounds like the cost is fairly minimal (some arithmetic per pointer conversion) all things considered. The original PR (https://github.com/golang/go/issues/22218#issuecomment-463007572) suggests it would be lightweight, too. It sounds more like it's behind -d just because it's somewhat experimental and because existing code was known to violate the rules, not because it's expensive.

[lidavidm]

It's also not the concurrency itself that's the issue here (i.e. putting a lock around getting a new cursor doesn't change anything).

[lidavidm]

I added some instrumentation to print out pointers in various places but all seem to be in an entirely different space than what Go is reporting as the problematic pointer. So it doesn't seem to be in the FFI bindings or in Arrow-Go, at least so far.

[lidavidm]

The next step will be to try building pyarrow 10.0.1 and replicating the issue, then cherry-picking the patch from 11.0.0 that we think is the fix, and confirming that it is indeed the fix.

[lidavidm]

Hmm, my locally-built copy of pyarrow 10.0.1 doesn't have this issue...

[lidavidm]

Non-concurrent reproducer:

import adbc_driver_flightsql.dbapi
import pyarrow


with adbc_driver_flightsql.dbapi.connect("grpc://localhost:12345") as conn:
    cursors = []
    while True:
        cur = conn.cursor()
        cursors.append(cur)
        cur.execute("SELECT 1")
        table = cur.fetch_arrow_table()
        del table

[lidavidm]

Independent connections aren't safe, either:

import concurrent.futures
from concurrent.futures import ThreadPoolExecutor
import adbc_driver_flightsql.dbapi
import pyarrow


def task():
    with adbc_driver_flightsql.dbapi.connect("grpc://localhost:12345") as conn:
        with conn.cursor() as cur:
            cur.execute("SELECT 1")
            cur.fetch_arrow_table()


with ThreadPoolExecutor() as ex:
    while True:
        futures = [ex.submit(task) for _ in range(23)]
        for future in concurrent.futures.as_completed(futures):
            future.result()

[lidavidm]

But they're OK on a single thread.

[lidavidm]

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 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 that we're following the rules of how to use 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:

// 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:

// 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:

		// 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 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:

	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:

  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:

// 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.
And this happens if Python/C code happens to come right after Go code, reuse the same stack memory, and manages to place a structure that it is about to pass to Go at exactly the right (wrong) place.

The Solution

Now that we know what happened, we just have to somehow clear the struct before it hits Go.
That's implemented here: apache/arrow#36670, along with some incidental fixes for things that were found as part of the testing.