runtime: print register state for all crashes (user panics, ...) #50294
Description
What version of Go are you using (go version)?
$ go version go version devel go1.18-2d1d548 Tue Dec 21 03:55:43 2021 +0000 linux/amd64
Does this issue reproduce with the latest release?
Yes.
What did you do?
See https://go.dev/play/p/ttzSoVd57ts?v=gotip
It crashes (due to nil dereference) as follows:
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x454746]
goroutine 1 [running]:
main.Square(0x4046d9?, 0x60?, 0x0?)
/tmp/sandbox1838486988/prog.go:7 +0x6
main.Passthrough(0x458a40?, 0xc0000021a0?)
/tmp/sandbox1838486988/prog.go:12 +0x1c
main.main()
/tmp/sandbox1838486988/prog.go:14 +0x25
Program exited.
What did you expect to see?
Context: internal ABI specification
I expected to be able to see at least one of the input arguments to the crashing function Square() as they are still live. At the point of the crash, the RAX register used to pass the first parameter has been clobbered, but its state gives valuable input about what the original value of the first parameter was. The second parameter can be found in RBX untouched.
The disassembly is as follows (truncated, annotated):
0000000000454b40 <main.Square>:
454b40: 48 0f af c3 imul %rbx,%rax
454b44: 31 c9 xor %ecx,%ecx
454b46: 48 03 01 add (%rcx),%rax ; CRASH by nil dereference
454b49: c3 ret
0000000000454b60 <main.Passthrough>:
454b60: 49 3b 66 10 cmp 0x10(%r14),%rsp
454b64: 76 20 jbe 454b86 <main.Passthrough+0x26>
454b66: 48 83 ec 20 sub $0x20,%rsp
454b6a: 48 89 6c 24 18 mov %rbp,0x18(%rsp)
454b6f: 48 8d 6c 24 18 lea 0x18(%rsp),%rbp
454b74: 48 89 d9 mov %rbx,%rcx
454b77: e8 c4 ff ff ff call 454b40 <main.Square>
454b7c: 48 8b 6c 24 18 mov 0x18(%rsp),%rbp
454b81: 48 83 c4 20 add $0x20,%rsp
454b85: c3 ret
454b86: 48 89 44 24 08 mov %rax,0x8(%rsp)
454b8b: 48 89 5c 24 10 mov %rbx,0x10(%rsp)
454b90: e8 8b cd ff ff call 451920 <runtime.morestack_noctxt.abi0>
454b95: 48 8b 44 24 08 mov 0x8(%rsp),%rax
454b9a: 48 8b 5c 24 10 mov 0x10(%rsp),%rbx
454b9f: 90 nop
454ba0: eb be jmp 454b60 <main.Passthrough>
0000000000454bc0 <main.main>:
454bc0: 49 3b 66 10 cmp 0x10(%r14),%rsp
454bc4: 76 29 jbe 454bef <main.main+0x2f>
454bc6: 48 83 ec 18 sub $0x18,%rsp
454bca: 48 89 6c 24 10 mov %rbp,0x10(%rsp)
454bcf: 48 8d 6c 24 10 lea 0x10(%rsp),%rbp
454bd4: b8 09 00 00 00 mov $0x9,%eax
454bd9: 48 89 c3 mov %rax,%rbx
454bdc: 0f 1f 40 00 nopl 0x0(%rax)
454be0: e8 7b ff ff ff call 454b60 <main.Passthrough>
454be5: 48 8b 6c 24 10 mov 0x10(%rsp),%rbp
454bea: 48 83 c4 18 add $0x18,%rsp
454bee: c3 ret
454bef: e8 2c cd ff ff call 451920 <runtime.morestack_noctxt.abi0>
454bf4: eb ca jmp 454bc0 <main.main>The same thing happens when using an actual panic to force a crash, but at least there we can see that the registers are being clobbered (annotated):
0000000000454b40 <main.Square>:
454b40: 49 3b 66 10 cmp 0x10(%r14),%rsp
454b44: 76 22 jbe 454b68 <main.Square+0x28>
454b46: 48 83 ec 18 sub $0x18,%rsp
454b4a: 48 89 6c 24 10 mov %rbp,0x10(%rsp)
454b4f: 48 8d 6c 24 10 lea 0x10(%rsp),%rbp
454b54: 48 8d 05 e5 44 00 00 lea 0x44e5(%rip),%rax # 459040 <type.*+0x4040> ; REGISTER CLOBBERED
454b5b: 48 8d 1d 26 16 02 00 lea 0x21626(%rip),%rbx # 476188 <runtime.mainPC+0x8> ; REGISTER CLOBBERED
454b62: e8 59 63 fd ff call 42aec0 <runtime.gopanic> ; PANIC
454b67: 90 nop
454b68: e8 b3 cd ff ff call 451920 <runtime.morestack_noctxt.abi0>
454b6d: eb d1 jmp 454b40 <main.Square>What did you see instead?
I expected that the parameter values in the stack trace would be as accurate as they could be, or at least more accurate than they are now. Now they contain values that aren't in any way related to the code that was running. The signal handler (likely) clobbers the registers state, which is why I believe we see values like 0x4046d9?, 0x60?, 0x0?. We can see the same values if we call panic() manually.
I've been told it would be a more involved project to improve the stack printer in such a way that it could take into account (better) the liveness, clobber state et cetera to get the "best possible estimate" for the parameter value. But a cheaper solution that would serve well in the interim would be to just dump the register state (all registers) when handling a crash. Then, a crash investigator can combine this information with an objdump to figure out whatever possible about the state of the crashing stack.
An argument raised was that dumping register state would be scary to users. Some counterpoints:
- Go already dumps registers when there is a fatal error in the runtime. I don't see why user panics should be different.
- When Go 1.17 introduced the regabi, the debugging experience for stack traces was weakened by the values being incorrect fairly often. It used to be that register state wasn't quite so necessary because previously to Go 1.17 the parameters were generally correct. This change would improve the situation a bit again.
- The expected user of a stack trace is a developer, who may benefit from some insight into the computing stack. Even if the developer who first looks at the crash does not have the required experience to extract useful information, they may reroute that to an expert who can use it. If the register state is not printed as is currently the case, no-one can help.
- C++ crash handlers at the place I work always print the register state (but no arguments), and anecdotally (for me) it has been useful in the past.
cc @cherrymui @aclements who I've talked to about this.