runtime: stoplockedm: inconsistent locking

[bradfitz]

linux-386 at be596f0

https://build.golang.org/log/40f5c89dd04f3d7f0f5ebaf14636c25d814d3f65

...

##### ../misc/cgo/errors
test barrier-gcprog-struct-heap output does not contain expected error (failed with exit status 2)
=== test barrier-gcprog-struct-heap output ===
fatal error: stoplockedm: inconsistent locking
fatal error: runtime: internal error: misuse of lockOSThread/unlockOSThread

runtime stack:
runtime.throw(0x80a9482, 0x21)
	/tmp/workdir/go/src/runtime/panic.go:605 +0x7c
runtime.stoplockedm()
	/tmp/workdir/go/src/runtime/proc.go:1808 +0x13e
runtime.schedule()
	/tmp/workdir/go/src/runtime/proc.go:2203 +0x270
runtime.goschedImpl(0x197000e0)
	/tmp/workdir/go/src/runtime/proc.go:2323 +0xdc
runtime.gopreempt_m(0x197000e0)
	/tmp/workdir/go/src/runtime/proc.go:2351 +0x2c
runtime.newstack(0x0)
	/tmp/workdir/go/src/runtime/stack.go:1042 +0x23f
runtime.morestack()
	/tmp/workdir/go/src/runtime/asm_386.s:465 +0x77

goroutine 1 [running, locked to thread]:
	goroutine running on other thread; stack unavailable

runtime stack:
runtime.throw(0x80aaa6b, 0x3e)
	/tmp/workdir/go/src/runtime/panic.go:605 +0x7c
runtime.badunlockosthread()
	/tmp/workdir/go/src/runtime/proc.go:3206 +0x2b
runtime.systemstack(0x1971ca80)
	/tmp/workdir/go/src/runtime/asm_386.s:393 +0x5e
runtime.mstart()
	/tmp/workdir/go/src/runtime/proc.go:1125
=== end of test barrier-gcprog-struct-heap output ===
exit status 1
2017/08/03 21:34:59 Failed: exit status 1
2017/08/03 21:34:59 FAILED

/cc @aclements @ianlancetaylor

[ianlancetaylor]

This is the program in question:

package main

/*
#include <stdlib.h>
struct s { char *a[32769]; };
struct s2 { struct s f; };
struct s2 *f1() { return malloc(sizeof(struct s2)); }
void f2(struct s2 *p) {}
void f3(void *p) {}
*/
import "C"

import "unsafe"

func main() {
	p := C.f1()
	n := &C.struct_s{[32769]*C.char{new(C.char)}}
	p.f = *n
	C.f2(p)
	n.a[0] = nil
	C.f3(unsafe.Pointer(n))
}

The program is being run with GODEBUG=cgocheck=2 set in the environment. It is expected to throw fatal error: Go pointer stored into non-Go memory. The test failure is because the program failed with an unexpected throw.

I just ran the program 30,000 times and the error did not recur.

[ianlancetaylor]

Ah, but when I built the program with GOARCH=386 it failed after 2250 attempts.

[ianlancetaylor]

Here is the full stack trace of a failure:

fatal error: stoplockedm: inconsistent locking

runtime stack:
runtime.throw(0x80a9642, 0x21)
	/home/iant/go/src/runtime/panic.go:605 +0x7c fp=0xff889534 sp=0xff889528 pc=0x8068dcc
runtime.stoplockedm()
	/home/iant/go/src/runtime/proc.go:1808 +0x13e fp=0xff889544 sp=0xff889534 pc=0x806df2e
runtime.schedule()
	/home/iant/go/src/runtime/proc.go:2203 +0x270 fp=0xff889564 sp=0xff889544 pc=0x806f100
runtime.goschedImpl(0x186000e0)
	/home/iant/go/src/runtime/proc.go:2323 +0xdc fp=0xff889574 sp=0xff889564 pc=0x806f44c
runtime.gopreempt_m(0x186000e0)
	/home/iant/go/src/runtime/proc.go:2351 +0x2c fp=0xff88957c sp=0xff889574 pc=0x806f4fc
runtime.newstack(0x0)
	/home/iant/go/src/runtime/stack.go:1042 +0x23c fp=0xff889634 sp=0xff88957c pc=0x807b9ec
runtime.morestack()
	/home/iant/go/src/runtime/asm_386.s:465 +0x77 fp=0xff88963c sp=0xff889634 pc=0x8089717

goroutine 1 [runnable]:
runtime.activeModules(0x1860e000, 0x1, 0x2)
	/home/iant/go/src/runtime/symtab.go:412 +0x64 fp=0x1864bf38 sp=0x1864bf34 pc=0x807d924
runtime.cgoIsGoPointer(0x80df9a0, 0x8054001)
	/home/iant/go/src/runtime/cgocall.go:621 +0x1a fp=0x1864bf48 sp=0x1864bf38 pc=0x804b25a
runtime.cgoCheckWriteBarrier(0x18600168, 0x80df9a0)
	/home/iant/go/src/runtime/cgocheck.go:22 +0x11 fp=0x1864bf60 sp=0x1864bf48 pc=0x804b3c1
runtime.writebarrierptr(0x18600168, 0x80df9a0)
	/home/iant/go/src/runtime/mbarrier.go:204 +0x90 fp=0x1864bf78 sp=0x1864bf60 pc=0x80540f0
runtime.dolockOSThread(...)
	/home/iant/go/src/runtime/proc.go:3154
runtime.lockOSThread(...)
	/home/iant/go/src/runtime/proc.go:3170
runtime.cgocall(0x808f5c0, 0x1864bfa8, 0x0)
	/home/iant/go/src/runtime/cgocall.go:109 +0x130 fp=0x1864bf94 sp=0x1864bf78 pc=0x804a2e0
main._Cfunc_f1(0x0)
	command-line-arguments/_obj/_cgo_gotypes.go:51 +0x3b fp=0x1864bfa8 sp=0x1864bf94 pc=0x808f27b
main.main()
	/home/iant/foo8.go:16 +0x1e fp=0x1864bfc4 sp=0x1864bfa8 pc=0x808f38e
runtime.main()
	/home/iant/go/src/runtime/proc.go:185 +0x1f6 fp=0x1864bff0 sp=0x1864bfc4 pc=0x806a266
runtime.goexit()
	/home/iant/go/src/runtime/asm_386.s:1635 +0x1 fp=0x1864bff4 sp=0x1864bff0 pc=0x808b1f1
```

[ianlancetaylor]

The comment on doLockOSThread says "Do not allow preemption during this call, or else the m might be different in this function than in the caller." So the problem is straightforward enough: we are allowing preemption during the call because the write barrier calls the cgo checker which calls activeModules which is not marked nosplit.

[gopherbot]

Change https://golang.org/cl/53352 mentions this issue: runtime: mark activeModules nosplit/nowritebarrier

[ianlancetaylor]

CL 53352 has a fix and a test case that fails reliably with GOARCH=386 but never seems to fail with GOARCH=amd64. I don't know what the difference between 386 and amd64 is here.

[gopherbot]

Change https://golang.org/cl/53415 mentions this issue: misc/cgo/errors: update ptr.go comment