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

Jump to bottom

runtime: TestCallbackPanic internal lockOSThread error #47382

Closed
changkun opened this issue Jul 25, 2021 · 3 comments
Closed

runtime: TestCallbackPanic internal lockOSThread error #47382

changkun opened this issue Jul 25, 2021 · 3 comments
Labels
FrozenDueToAge

Comments

@changkun
Copy link
Member

changkun commented Jul 25, 2021 •
edited

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

$ go version
go version devel go1.17-0914646ab9 Fri Jul 23 18:10:55 2021 +0000 windows/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output
$ go env

What did you do?

While debugging CL 336550, a strage test case faulure because of a defer statement.

The syscall_Syscall6:

go/src/runtime/syscall_windows.go

Lines 483 to 495 in 0914646

//go:linkname syscall_Syscall6 syscall.Syscall6
//go:nosplit
//go:cgo_unsafe_args
func syscall_Syscall6(fn, nargs, a1, a2, a3, a4, a5, a6 uintptr) (r1, r2, err uintptr) {
lockOSThread()
defer unlockOSThread()
c := &getg().m.syscall
c.fn = fn
c.n = nargs
c.args = uintptr(noescape(unsafe.Pointer(&a1)))
cgocall(asmstdcallAddr, unsafe.Pointer(c))
return c.r1, c.r2, c.err
}

Change as follow:

//go:linkname syscall_Syscall6 syscall.Syscall6
//go:nosplit
//go:cgo_unsafe_args
func syscall_Syscall6(fn, nargs, a1, a2, a3, a4, a5, a6 uintptr) (r1, r2, err uintptr) {
	lockOSThread()
	c := &getg().m.syscall
	c.fn = fn
	c.n = nargs
	c.args = uintptr(noescape(unsafe.Pointer(&a1)))
	cgocall(asmstdcallAddr, unsafe.Pointer(c))
	unlockOSThread()
	return c.r1, c.r2, c.err
}

A similar CL 316650 may have a similar issue but does observe any panic yet.

What did you expect to see?

PS C:\Users\changkun\dev\go-gerrit\src\runtime> ..\..\bin\go.exe test -run=TestCallbackPanic -v
=== RUN   TestCallbackPanicLocked
--- PASS: TestCallbackPanicLocked (0.00s)
=== RUN   TestCallbackPanic
--- PASS: TestCallbackPanic (0.00s)
=== RUN   TestCallbackPanicLoop
--- PASS: TestCallbackPanicLoop (0.26s)
PASS
ok      runtime 0.328s

What did you see instead?

PS C:\Users\changkun\dev\go-gerrit\src\runtime> ..\..\bin\go.exe test -run=TestCallbackPanic -v
=== RUN   TestCallbackPanicLocked
--- PASS: TestCallbackPanicLocked (0.00s)
invalid m->lockedInt = 1
fatal error: === RUN   TestCallbackPanic
internal lockOSThread error
    syscall_windows_test.go:225: locked OS thread on exit from TestCallbackPanic        
--- FAIL: TestCallbackPanic (0.00s)
invalid m->lockedInt = 1
fatal error: internal lockOSThread error

runtime stack:
runtime.throw({0xf48e8e, 0x600000000})
        C:/Users/changkun/dev/go-gerrit/src/runtime/panic.go:1198 +0x76 fp=0x8a1a9ff710 sp=0x8a1a9ff6e0 pc=0xd4bd96
runtime.goexit0(0xc0000851e0)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:3673 +0x26d fp=0x8a1a9ff748 sp=0x8a1a9ff710 pc=0xd556ad
runtime.mcall()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:307 +0x4a fp=0x8a1a9ff758 sp=0x8a1a9ff748 pc=0xd7ffaa

goroutine 1 [runnable]:
runtime.gopark(0xc0000c1a70, 0xd1e174, 0x1c, 0x0, 0xc0000c1a20)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:366 +0xd6 fp=0xc0000c19f0 sp=0xc0000c19d0 pc=0xd4e6f6
runtime.chanrecv(0xc00005e070, 0xc0000c1aef, 0x1)
        C:/Users/changkun/dev/go-gerrit/src/runtime/chan.go:576 +0x56c fp=0xc0000c1a80 sp=0xc0000c19f0 pc=0xd16c0c
runtime.chanrecv1(0xf418ba, 0xc000004018)
        C:/Users/changkun/dev/go-gerrit/src/runtime/chan.go:439 +0x18 fp=0xc0000c1aa8 sp=0xc0000c1a80 pc=0xd16638
testing.(*T).Run(0xc000084ea0, {0xf418ba, 0xd84ef3}, 0xf58238)
        C:/Users/changkun/dev/go-gerrit/src/testing/testing.go:1303 +0x375 fp=0xc0000c1b48 sp=0xc0000c1aa8 pc=0xdf8c55
testing.runTests.func1(0xc0000b8870)
        C:/Users/changkun/dev/go-gerrit/src/testing/testing.go:1594 +0x6e fp=0xc0000c1b98 sp=0xc0000c1b48 pc=0xdfa86e
testing.tRunner(0xc000084ea0, 0xc0000c1ca0)
        C:/Users/changkun/dev/go-gerrit/src/testing/testing.go:1255 +0x102 fp=0xc0000c1be8 sp=0xc0000c1b98 pc=0xdf8002
testing.runTests(0xc0000d0080, {0x10eb180, 0x175, 0x175}, {0xc0000d5ea8, 0xc0000d5f10, 0x10ef200})
        C:/Users/changkun/dev/go-gerrit/src/testing/testing.go:1592 +0x43f fp=0xc0000c1cd0 sp=0xc0000c1be8 pc=0xdfa71f
testing.(*M).Run(0xc0000d0080)
        C:/Users/changkun/dev/go-gerrit/src/testing/testing.go:1500 +0x51d fp=0xc0000c1ea0 sp=0xc0000c1cd0 pc=0xdf947d
runtime_test.TestMain(0x1010167603d0108)
        C:/Users/changkun/dev/go-gerrit/src/runtime/crash_test.go:27 +0x1d fp=0xc0000c1ee0 sp=0xc0000c1ea0 pc=0xe57e1d
main.main()
        _testmain.go:1301 +0x165 fp=0xc0000c1f80 sp=0xc0000c1ee0 pc=0xedd105
runtime.main()
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:255 +0x217 fp=0xc0000c1fe0 sp=0xc0000c1f80 pc=0xd4e357
runtime.goexit()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc0000c1fe8 sp=0xc0000c1fe0 pc=0xd82341

goroutine 2 [force gc (idle)]:
runtime.gopark(0x0, 0x0, 0x0, 0x0, 0x0)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:366 +0xd6 fp=0xc000053fb0 sp=0xc000053f90 pc=0xd4e6f6
runtime.goparkunlock(...)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:372
runtime.forcegchelper()
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:306 +0xb1 fp=0xc000053fe0 sp=0xc000053fb0 pc=0xd4e591
runtime.goexit()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc000053fe8 sp=0xc000053fe0 pc=0xd82341
created by runtime.init.7
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:294 +0x25

goroutine 3 [GC sweep wait]:
runtime.gopark(0x0, 0x0, 0x0, 0x0, 0x0)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:366 +0xd6 fp=0xc000055fb0 sp=0xc000055f90 pc=0xd4e6f6
runtime.goparkunlock(...)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:372
runtime.bgsweep()
        C:/Users/changkun/dev/go-gerrit/src/runtime/mgcsweep.go:163 +0x88 fp=0xc000055fe0 sp=0xc000055fb0 pc=0xd36028
runtime.goexit()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc000055fe8 sp=0xc000055fe0 pc=0xd82341
created by runtime.gcenable
        C:/Users/changkun/dev/go-gerrit/src/runtime/mgc.go:181 +0x55

goroutine 4 [GC scavenge wait]:
runtime.gopark(0x0, 0x0, 0x0, 0x0, 0x0)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:366 +0xd6 fp=0xc000065f80 sp=0xc000065f60 pc=0xd4e6f6
runtime.goparkunlock(...)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:372
runtime.bgscavenge()
        C:/Users/changkun/dev/go-gerrit/src/runtime/mgcscavenge.go:265 +0xcd fp=0xc000065fe0 sp=0xc000065f80 pc=0xd3412d
runtime.goexit()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc000065fe8 sp=0xc000065fe0 pc=0xd82341
created by runtime.gcenable
        C:/Users/changkun/dev/go-gerrit/src/runtime/mgc.go:182 +0x65

goroutine 18 [finalizer wait]:
runtime.gopark(0xd4ea92, 0xc000057f70, 0x51, 0xb1, 0x10ce9c0)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:366 +0xd6 fp=0xc000057e30 sp=0xc000057e10 pc=0xd4e6f6
runtime.goparkunlock(...)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:372
runtime.runfinq()
        C:/Users/changkun/dev/go-gerrit/src/runtime/mfinal.go:177 +0xb3 fp=0xc000057fe0 sp=0xc000057e30 pc=0xd2b613
runtime.goexit()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc000057fe8 sp=0xc000057fe0 pc=0xd82341
created by runtime.createfing
        C:/Users/changkun/dev/go-gerrit/src/runtime/mfinal.go:157 +0x45

runtime stack:
runtime.throw({0xf48e8e, 0x600000000})
        C:/Users/changkun/dev/go-gerrit/src/runtime/panic.go:1198 +0x76 fp=0x8a1b5ffa60 sp=0x8a1b5ffa30 pc=0xd4bd96
runtime.goexit0(0xc000051040)
        C:/Users/changkun/dev/go-gerrit/src/runtime/proc.go:3673 +0x26d fp=0x8a1b5ffa98 sp=0x8a1b5ffa60 pc=0xd556ad
runtime.mcall()
        C:/Users/changkun/dev/go-gerrit/src/runtime/asm_amd64.s:307 +0x4a fp=0x8a1b5ffaa8 sp=0x8a1b5ffa98 pc=0xd7ffaa
exit status 2
FAIL    runtime 0.091s
@WangLeonard
Copy link
Contributor

Hi, I think this may be normal?

TestCallbackPanic -> nestedCall(t, f) -> d.Proc("EnumTimeFormatsEx").Call -> Syscall6 -> syscall_Syscall6 -> lockOSThread() -> cgocall(f) -> asmcgocall -> panic

asmcgocall will switch to g0 ? Sorry for the processing in panic in g0. I'm not sure.

But since there is no defer unlockOSThread(), when panic returns to the defer of TestCallbackPanic, unlockOSThread is not executed.

Further, runtime.LockedOSThread() will return true and t.Fatal will be triggered

func lockedOSThread() bool {
	gp := getg()
	return gp.lockedm != 0 && gp.m.lockedg != 0
}
defer func() {
  s := recover()
  ……
  if !runtime.LockedOSThread() {
    t.Fatal("lost lock on OS thread after panic")
  }
}()

and then

t.Fatal -> FailNow -> Goexit -> goexit1 -> goexit0

The check was triggered again, resulting in a second print

if _g_.m.lockedInt != 0 {
  print("invalid m->lockedInt = ", _g_.m.lockedInt, "\n")
  throw("internal lockOSThread error")
}

Before the modification, due to the existence of defer, unlockOSThread will be executed after panic
When panic returns to the defer of TestCallbackPanic, runtime.LockedOSThread() will return false, and everything is fine

But according to CL316650, maybe this is acceptable?
I wonder if the test case can be modified, Maybe this needs to wait for an official response.

@changkun
Copy link
Member Author

@WangLeonard Thanks for the investigation. Yes, your analysis matches what I originally wanted to point out. The CL 336550 would be nice to unify all syscalls into syscallN, but with this runtime check, the unification seems less possible (I could not think of a way to avoid falling into special cases at the moment).

@changkun
Copy link
Member Author

Looks like nothing needs to do here. See a great explanation here.

@golang golang locked and limited conversation to collaborators Jul 26, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@changkun @gopherbot @WangLeonard