runtime: infinite recursion on windows triggered by morestack

[kjk]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.9rc2 windows/amd64

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

set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\Users\kjk\src\go
set GORACE=
set GOROOT=C:\Go
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0
set CXX=g++
set CGO_ENABLED=1
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config

What did you do?

This is a continuation of #20975 so the same repro program (https://github.com/kjk/go20975) built in 64bit mode.

What did you expect to see?

No infinite recursion.

What did you see instead?

This time I used https://github.com/kjk/cv2pdb to convert dwarf to pdb so that I can get symbols in windbg.

I ran repro program under windbg.

The crash is:

 # RetAddr           : Args to Child                                                           : Call Site
00 00000000`0043cc0b : 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b : go20975!runtime.morestack+0x10 [C:\Go\src\runtime\asm_amd64.s @ 377] 
01 00000000`00451a56 : 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 : go20975!runtime.sigpanic+0x18b [C:\Go\src\runtime\signal_windows.go @ 152] 
02 00000000`0043cc0b : 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
03 00000000`00451a56 : 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 : go20975!runtime.sigpanic+0x18b [C:\Go\src\runtime\signal_windows.go @ 152] 
04 00000000`0043cc0b : 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
05 00000000`00451a56 : 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 : go20975!runtime.sigpanic+0x18b [C:\Go\src\runtime\signal_windows.go @ 152] 
06 00000000`0043cc0b : 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
07 00000000`00451a56 : 00000000`0043cc0b 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 : go20975!runtime.sigpanic+0x18b [C:\Go\src\runtime\signal_windows.go @ 152] 
08 00000000`0043cc0b : 00000000`00451a56 00000000`0043cc0b 00000000`00451a56 00000000`0045104a : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
09 00000000`00451a56 : 00000000`0043cc0b 00000000`00451a56 00000000`0045104a 00000000`004519ee : go20975!runtime.sigpanic+0x18b [C:\Go\src\runtime\signal_windows.go @ 152] 
0a 00000000`0043cc0b : 00000000`00451a56 00000000`0045104a 00000000`004519ee 00000000`004304f0 : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
0b 00000000`00451a56 : 00000000`0045104a 00000000`004519ee 00000000`004304f0 00000000`00b9fef0 : go20975!runtime.sigpanic+0x18b [C:\Go\src\runtime\signal_windows.go @ 152] 
0c 00000000`0045104a : 00000000`004519ee 00000000`004304f0 00000000`00b9fef0 00000000`00000000 : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
0d 00000000`004519ee : 00000000`004304f0 00000000`00b9fef0 00000000`00000000 00007ffa`59b6e618 : go20975!runtime.exitsyscallfast.func1+0xaa [C:\Go\src\runtime\proc.go @ 2717] 
0e 00000000`004304f0 : 00000000`00b9fef0 00000000`00000000 00007ffa`59b6e618 00000000`00455804 : go20975!runtime.systemstack+0x7e [C:\Go\src\runtime\asm_amd64.s @ 347] 
0f 00000000`00b9fef0 : 00000000`00000000 00007ffa`59b6e618 00000000`00455804 00000000`006307d8 : go20975!runtime.mstart [C:\Go\src\runtime\proc.go @ 1125] 
10 00000000`00000000 : 00007ffa`59b6e618 00000000`00455804 00000000`006307d8 00000000`00b90e00 : 0xb9fef0

TEXT runtime·morestack(SB),NOSPLIT,$0-0
	// Cannot grow scheduler stack (m->g0).
	get_tls(CX)
	MOVQ	g(CX), BX
	MOVQ	g_m(BX), BX
	MOVQ	m_g0(BX), SI
	CMPQ	g(CX), SI
	JNE	3(PC)
	CALL	runtime·badmorestackg0(SB)
	INT	$3

INT $3 is executed which triggers runtime.sigpanic. I assume sigpanic does stack check, calls morestack and that does INT $3 again. Infite loop happens and eventually crash will happen.

[kjk]

So I'm stepping through the assembly and there's more fishy stuff.

After int 3 we end up in:

00000000`00451a56 03488b          add     ecx,dword ptr [rax-75h] ds:ffffffff`ffffffa2=????????
00000000`00451a59 7350            jae     go20975!runtime.morestack+0x7b (00000000`00451aab)
00000000`00451a5b 4839b100000000  cmp     qword ptr [rcx],rsi

However, at that point rax is 0x17, so trying to de-reference [rax-75h] throws an exception:

0:000> t
(1830.205c): Access violation - code c0000005 (first chance)

That doesn't make sense to me unless this is a trick to just trigger an exception.

Here's a what gets executed, according to windbg, when single-stepping from int 3 to calling morestack again:

go20975!runtime.morestack+0x25:
00000000`00451a55 cd03            int     3
0:000> p
WARNING: This break is not a step/trace completion.
The last command has been cleared to prevent
accidental continuation of this unrelated event.
Check the event, location and thread before resuming.
(1830.205c): Break instruction exception - code 80000003 (first chance)
go20975!runtime.morestack+0x26:
00000000`00451a56 03488b          add     ecx,dword ptr [rax-75h] ds:ffffffff`ffffffa2=????????
0:000> t
(1830.205c): Access violation - code c0000005 (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
go20975!runtime.morestack+0x26:
00000000`00451a56 03488b          add     ecx,dword ptr [rax-75h] ds:ffffffff`ffffffa2=????????
0:000> t
go20975!runtime.sigpanic+0x9:
00000000`0043ca89 488b8900000000  mov     rcx,qword ptr [rcx] ds:00000000`0077b438={go20975!runtimeg0 (00000000`0077b0a0)}
0:000> t
go20975!runtime.morestack_noctxt:
00000000`00451ad0 31d2            xor     edx,edx
0:000> t
go20975!runtime.morestack_noctxt+0x2:
00000000`00451ad2 e959ffffff      jmp     go20975!runtime.morestack (00000000`00451a30)
0:000> t
go20975!runtime.morestack:
00000000`00451a30 65488b0c2528000000 mov   rcx,qword ptr gs:[28h] gs:00000000`00000028=????????????????

I don't get how executing:

go20975!runtime.sigpanic+0x9:
00000000`0043ca89 488b8900000000  mov     rcx,qword ptr [rcx] ds:00000000`0077b438={go20975!runtimeg0 (00000000`0077b0a0)}

ends up going to go20975!runtime.morestack_noctxt == 0000000000451ad0`.

[mvdan]

Just to clarify, is this when building the program, or when running it?

Does this happen with 1.8?

CC @aclements

[mvdan]

Also, if this was an infinite recursion, wouldn't you end up with a panic or crash of some sort? I don't know what windbg is, so perhaps there's something I'm missing.

[kjk]

Eventually the process will go away due to stack overflow exception. In this scenario runtime is incapable of handling it and generating a proper panic.

[alexbrainman]

In this scenario runtime is incapable of handling it and generating a proper panic.

I would not expect Go to generate proper panic after executing INT $3. I will let Austin decide if something needs to be done here.

Alex

[aclements]

I'd like to understand how we wound up in morestack without any remaining system stack space in the first place. Once we hit the INT $3, it would be nice to fail more gracefully, but things are toast anyway.

If there any way MSHTML could be calling back into Go code while deep in the stack?

If not, and I'm grasping at straws here, but my guess is that the C "syscall" code (which runs on the system stack) is running out of stack space, which invokes a Windows exception handler registered by the runtime, which also attempts to run on the system stack and fails when it sees there's no stack left. @alexbrainman, I know very little about how Windows exception handlers work; does this seem like a plausible explanation?

(Notably, on UNIX platforms, the signal handler runs on yet another stack that's only for signal handling, so even if we run out of space on the system stack, we have a little more backup room in which to fail gracefully.)

[aclements]

Actually, this is sort of interesting, though I'm not sure what to make of it:

0c 00000000`0045104a : 00000000`004519ee 00000000`004304f0 00000000`00b9fef0 00000000`00000000 : go20975!runtime.morestack+0x26 [C:\Go\src\runtime\asm_amd64.s @ 382] 
0d 00000000`004519ee : 00000000`004304f0 00000000`00b9fef0 00000000`00000000 00007ffa`59b6e618 : go20975!runtime.exitsyscallfast.func1+0xaa [C:\Go\src\runtime\proc.go @ 2717] 

exitsyscallfast.func1 is specifically the closure that does throw("exitsyscall: syscall frame is no longer valid"). This indicates that we tried to return from the system call (though why that would be, I'm not sure), but the stack got unwound or the SP just changed completely. Then, we tried to switch to the system stack to report this, but it was full, leading to a cascade of other problems.

@kjk, can you put a breakpoint in exitsyscall at the first call to systemstack (inside the if getcallersp(unsafe.Pointer(&dummy)) > g.syscallsp`) and see what the call stack there is?

[kjk]

@aclements Please also read comments #20975 (comment) and below as this is the same issue and there is more detail there.

To summarize my guesses at this point:

It's not caused by running out of stack space.

morestack is called unconditionally (i.e. regardless of how much stack is left) by the closure passed to systemstack in exitsyscallfast.func1.

When morestack is called there's plenty of stack but it detects that it's being called on scheduler stack (g.m.g0 == g) which shouldn't happen because systemstack is supposed to ensure that it's, well, system stack. There seems to be a missed case in that logic.

When morestack detects this invariant being violated, it does int 3 to trigger debugger and make debugging easy.

It seems to be 64-bit only so I assume it's some of the arch-specific runtime assembly routines.

mshtml per se doesn't call Go but there are plenty of C->Go->C transitions because of how Windows message processing works.

Each window has a callback (called wndproc) responsible for handling message for that window. In Windows every control (a button, listview, browser view etc.) is a window.

To add custom handling of messages we need to provide our own wndproc callback, which must be called via C->Go trampoline. When that callback is not interested in the message, we need to call the original wndproc for that message, which is Go->C transition.

So every GUI windows program has a high rate of C->Go and Go->C transitions, especially those using https://github.com/lxn/walk/ library, as it hoooks wndproc for all windows it creates.

This also makes debugging with breakpoints impossible. I've spent several hours setting breakpoints at various points and stepping through the code but the same code works correctly the first 1000 times and then fails.

To summarize my beliefs:

• not caused by running out of stack
• caused by systemstack failing to switch to system stack before calling its closure and remaining on scheduler stack
• 64-bit only
• not deterministic but correlated to high rate of C->Go and Go->C transitions
• most likely a bug in runtime.systemstack in asm_arm64.s

The most promising approach would be to instrument systemstack to add the same check that morestack does but when exiting systemstack, to catch bad condition (remaining on scheduler stack) earlier.

[aclements]

@kjk, systemstack is extremely well-trodden code. Obviously it's not impossible that it contains a bug, but that's way down on my list of candidates.

morestack is called unconditionally (i.e. regardless of how much stack is left) by the closure passed to systemstack in exitsyscallfast.func1.

Why do you say that? It never makes sense to call morestack unconditionally, and, looking at the disassembly of exitsyscallfast.func1, it clearly does check the stack bound before calling morestack, as it's supposed to.

When morestack is called there's plenty of stack but it detects that it's being called on scheduler stack (g.m.g0 == g) which shouldn't happen because systemstack is supposed to ensure that it's, well, system stack.

This isn't quite right. There is no separate "scheduler stack", there's just the user stack and the system stack (and the signal stack on UNIX). If g.m.g0 == g, then you're on the system stack. So, systemstack is supposed to put you on the system stack, at which point g.m.g0 == g, and any call to morestack should panic.

What makes you say there's plenty of stack when it calls morestack? I didn't see evidence for that here or on the other issue (I may have just missed it; there are a lot of posts).

To add custom handling of messages we need to provide our own wndproc callback, which must be called via C->Go trampoline.

Can you point me to where your code is doing this? Normally this would go through the cgo callback paths, but since your application isn't using cgo, I'm curious how this is being done.

Given the C->Go callbacks, this is all precisely the behavior I would expect if C code were using up the system stack and then calling back into Go code.

(From my earlier post:)

exitsyscallfast.func1 is specifically the closure that does throw("exitsyscall: syscall frame is no longer valid").

Oops, I'd missed the fast in there, so I was looking at the wrong closure. Unfortunately, I would expect exitsyscallfast.func1 to be called quite frequently in normal operation, so setting a breakpoint there isn't useful. (But it does mean the SP probably isn't getting totally trashed like I thought.)

[kjk]

Like I said, those are guesses, you're more likely to be right than me.

There is no separate "scheduler stack"

I'm just parroting back terminology used by the code e.g.

go/src/runtime/asm_arm64.s

Line 271 in 3216e0c

// Cannot grow scheduler stack (m->g0).

What makes you say there's plenty of stack when it calls morestack?

I've tried the repro with ridiculously large (16 MB) stack and got the same thing.

In the debugger, I printed the callstack and it was relatively short from main().

Either way, this particular issue is due to morestack detecting an internal inconsistency (and not being able to handle it via somewhat controlled panic which eventually triggering windows exception that silently kills the process).

Given the C->Go callbacks, this is all precisely the behavior I would expect if C code were using up the system stack and then calling back into Go code.

It's also consistent with being confused about which stack the code is on.

If the code is confused about which stack it is on, then we might be on a thread with plenty of stack but "needs to grow stack" check is done on the wrong stack, wrongly detects need to expand stack, calls morestack which detects it's the wrong stack and does int 3.

Can you point me to where your code is doing this?

On windows syscall.Syscal does Go->C call and syscall.NewCallback creates C->Go callback.

This is all done in the lnx/walk library:

• https://github.com/lxn/walk/blob/master/window.go#L318 : defaultWndProc is Go function turned into defaultWndProcPtr C->Go trampoline
• https://github.com/lxn/walk/blob/master/window.go#L329, https://github.com/lxn/walk/blob/master/window.go#L354 : for your own windows, the wndproc is passed when a window class is registered. You then create a window using a class and wndproc will be called by Windows to process all messages
• https://github.com/lxn/walk/blob/master/window.go#L422 : you can also "subclass" Windows widgets (like a button) by replacing default wndproc (provided by Windows) with your own callback, which is what lxn/walk does for all windows to provide some common functionality
• https://github.com/lxn/walk/blob/master/window.go#L422 : the Go callback called from C (win32 OS code)
• https://github.com/lxn/walk/blob/master/window.go#L1360 : Go wndproc callback often calls the original OS wndproc, which causes Go->C transition

Windows GUI code is roughly this (https://github.com/lxn/walk/blob/2d327b4a1aba7cda2a365bc566fd60ea6bd4c8bf/form.go#L365):

• there's an infinite loop calling (Windows OS functions) GetMessage()/DispatchMessage() (until getting a message indicating the app has been closed)
• DispatchMessage() is a win32 OS function so that's Go -> C transition. It determines which window is target of the message and calls its wndproc. In our case it causes C -> Go transition as wndproc is a trampoline to a Go code
• often Go callback doesn't process the message and calls the original C wndproc, which is Go -> C transition
• then they all unwind, go back to Go code that repeats GetMessage()/DispatchMessage() until the user closes the window, triggering the exit

It's unavoidable to get Go -> C -> Go -> C in Windows GUI programs. Using cgo is not necessary for that.

[alexbrainman]

is running out of stack space, which invokes a Windows exception handler registered by the runtime, which also attempts to run on the system stack and fails when it sees there's no stack left.

Windows exception handler calls runtime.sigtramp. The runtime.sigtramp will run on scheduler stack. Also see _StackSystem is used to make sure we always have enough room to run exception handler.

Normally this would go through the cgo callback paths, but since your application isn't using cgo, I'm curious how this is being done.

If you are interested to see simple Windows GUI app, you can download d8b239ff60a62c3f50f7eb5994221b50ba055cf2 commit (initial commit) of https://github.com/alexbrainman/gowingui

Alex