-
Notifications
You must be signed in to change notification settings - Fork 2.3k
multi: standardize panic recovery at async boundaries #11097
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
base: master
Are you sure you want to change the base?
Changes from all commits
073992f
2ced903
e6e5424
b7d94fa
acd1414
3742672
8211025
2292f6d
2bd8247
e992ba5
eb79cfb
42dd2ec
4080b75
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,134 @@ | ||
| package fn | ||
|
|
||
| import ( | ||
| "bytes" | ||
| "context" | ||
| "errors" | ||
| "fmt" | ||
| "log/slog" | ||
| "runtime/debug" | ||
| ) | ||
|
|
||
| const ( | ||
| // maxPanicStackSize is the largest recovered-panic stack trace returned | ||
| // by these helpers. Bounding it keeps repeated reports from consuming | ||
| // excessive log space. | ||
| maxPanicStackSize = 8192 | ||
|
|
||
| // panicStackTruncatedMsg is appended in place of whatever we cut, so | ||
| // that whoever reads the log can tell the trace is incomplete instead | ||
| // of assuming it ended where it stops. | ||
| panicStackTruncatedMsg = "\n... stack trace truncated ..." | ||
| ) | ||
|
|
||
| // errRecoveredPanic is the sentinel error attached to every structured log | ||
| // record emitted for a recovered panic. | ||
| var errRecoveredPanic = errors.New("recovered panic") | ||
|
|
||
| // Panic carries the details of a panic we stopped: the value handed to panic(), | ||
| // and a stack trace bounded to a size that's safe to log. The trace still | ||
| // covers the frames the panic came from, not just the point we caught it at. | ||
| type Panic struct { | ||
| // Value is whatever was passed to panic(). | ||
| Value any | ||
|
|
||
| // Stack is the stack trace of the panicking goroutine, truncated to a | ||
| // bounded size. | ||
| Stack []byte | ||
| } | ||
|
|
||
| // PanicLogger is the minimal structured-logging surface needed to report a | ||
| // recovered panic. Keeping the interface here avoids coupling fn to a concrete | ||
| // logging package. | ||
| type PanicLogger interface { | ||
| ErrorS(context.Context, string, error, ...any) | ||
| } | ||
|
|
||
| // LogRecoveredPanic records a recovered panic in a consistent structured | ||
| // format. The logger's subsystem and the captured stack identify where the | ||
| // panic was recovered. Callers can attach domain-specific context as additional | ||
| // structured attributes. | ||
| // | ||
| // Reporting is best effort. A panic while formatting or writing the record is | ||
| // recovered so the reporting path can return normally. | ||
| func LogRecoveredPanic(ctx context.Context, logger PanicLogger, | ||
| p Panic, extraAttrs ...any) { | ||
|
|
||
| if logger == nil { | ||
| return | ||
| } | ||
|
|
||
| // A panic in the logging path must not interrupt the caller's panic | ||
| // containment and cleanup. | ||
| defer func() { | ||
| _ = recover() | ||
| }() | ||
|
|
||
| attrs := []any{ | ||
| slog.String("panic_type", fmt.Sprintf("%T", p.Value)), | ||
| slog.Any("panic_value", p.Value), | ||
| slog.String("stack", string(p.Stack)), | ||
| } | ||
| attrs = append(attrs, extraAttrs...) | ||
|
|
||
| logger.ErrorS( | ||
| ctx, "Recovered panic", errRecoveredPanic, attrs..., | ||
| ) | ||
| } | ||
|
|
||
| // RecoverPanic stops a panic from unwinding the calling goroutine any further | ||
| // and hands the details to onPanic. If the goroutine isn't panicking, onPanic | ||
| // is never called and no stack is captured. | ||
| // | ||
| // This MUST be deferred directly: | ||
| // | ||
| // defer fn.RecoverPanic(func(p fn.Panic) { | ||
| // log.Errorf("recovered: %v\n%s", p.Value, p.Stack) | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This example contradicts the PR's own goal of standardized structured reporting. I would provide this example defer fn.RecoverPanic(func(p fn.Panic) {
fn.LogRecoveredPanic(ctx, s.log, p)
// ...subsystem-specific cleanup...
}) |
||
| // }) | ||
| // | ||
| // Wrapping it in a closure instead, as in | ||
| // `defer func() { fn.RecoverPanic(..) }()`, silently does nothing: the language | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. We could add a tiny analyzer to check for this misuse. The recommended fix: a tiny go/analysis analyzer in tools/linters/ _ right next to ll.go, registered the same way as a module plugin in The core is about 40 lines: // tools/linters/deferrecover.go
func run(pass *analysis.Pass) (any, error) {
inspect := pass.ResultOf[inspect.Analyzer].(*inspector.Inspector)
inspect.Preorder([]ast.Node{(*ast.CallExpr)(nil)}, func(n ast.Node) {
call := n.(*ast.CallExpr)
// Resolve the callee by type, not name: catches
// fn/v2.RecoverPanic regardless of import alias.
sel, ok := call.Fun.(*ast.SelectorExpr)
if !ok || pass.TypesInfo.Selections[sel] != nil {
return
}
obj := pass.TypesInfo.Uses[sel.Sel]
if obj == nil || obj.Pkg() == nil ||
obj.Pkg().Path() != "github.com/lightningnetwork/lnd/fn/v2" ||
obj.Name() != "RecoverPanic" {
return
}
// The call is fine iff its parent is a defer of this call.
// (track parentage via a stack or a second pass over DeferStmts)
if !directlyDeferred {
pass.Reportf(call.Pos(),
"fn.RecoverPanic only works when deferred directly: "+
"use `defer fn.RecoverPanic(...)` _ wrapping it "+
"in a closure silently recovers nothing")
}
})
return nil, nil
}ymmv |
||
| // only lets recover() stop a panic when it's called by the deferred function | ||
| // itself, so one frame further down it returns nil and the panic carries on | ||
| // unwinding. | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Add the following for proper documentation:
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The last line wouldn't be true anymore if you apply my suggestion from #11097 (comment) |
||
| func RecoverPanic(onPanic func(Panic)) { | ||
| r := recover() | ||
| if r == nil { | ||
| return | ||
| } | ||
|
|
||
| onPanic(Panic{ | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. No nil guard and no internal recovery around the callback: a nil // RecoverPanic stops a panic from unwinding the calling goroutine any
// further and hands the details to onPanic. ...
func RecoverPanic(onPanic func(Panic)) {
r := recover()
if r == nil {
return
}
// A nil callback would panic below, turning containment into a
// crash.
if onPanic == nil {
return
}
p := Panic{
Value: r,
Stack: TruncatePanicStack(debug.Stack()),
}
// The original panic has been consumed at this point, so a panic
// inside onPanic is a NEW panic that nothing else will catch. Arm a
// second recover that stays pending while the callback runs. There
// is no logger available here, and the logging path itself may be
// the thing that failed, so fall back to stderr _ the same place
// the runtime reports unhandled panics.
defer func() {
if r2 := recover(); r2 != nil {
fmt.Fprintf(os.Stderr,
"fn: panic handler panicked: %v (while "+
"containing: %v)\n%s", r2, r,
TruncatePanicStack(debug.Stack()),
)
}
}()
onPanic(p)
} |
||
| Value: r, | ||
| Stack: TruncatePanicStack(debug.Stack()), | ||
| }) | ||
| } | ||
|
|
||
| // PanicStack returns the stack trace of the calling goroutine, bounded to the | ||
| // configured size. | ||
| func PanicStack() []byte { | ||
| return TruncatePanicStack(debug.Stack()) | ||
| } | ||
|
|
||
| // TruncatePanicStack caps a panic stack trace at a bounded size. Where it can, | ||
| // it cuts on a line boundary so the last frame in the log stays readable rather | ||
| // than ending mid-token, and it marks the cut so the trace doesn't look | ||
| // complete. | ||
| func TruncatePanicStack(stack []byte) []byte { | ||
| if len(stack) <= maxPanicStackSize { | ||
| return stack | ||
| } | ||
|
|
||
| suffix := []byte(panicStackTruncatedMsg) | ||
| maxStackLen := maxPanicStackSize - len(suffix) | ||
| searchStack := stack[:maxStackLen+1] | ||
| newLineIndex := bytes.LastIndexByte(searchStack, '\n') | ||
| if newLineIndex > 0 { | ||
| maxStackLen = newLineIndex | ||
| } | ||
|
|
||
| truncatedStack := make([]byte, 0, maxStackLen+len(suffix)) | ||
| truncatedStack = append(truncatedStack, stack[:maxStackLen]...) | ||
| truncatedStack = append(truncatedStack, suffix...) | ||
|
|
||
| return truncatedStack | ||
| } | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Before this PR we recovered from panic in the gossiper and emitted the stack trace at Debug level.
A remote peer with a panic-inducing gossip message now generates ~8 KiB of ERROR logs per attempt; per-event size is bounded but repetition is not, and there is no rate limit.
Fix: keep the stack trace at Debug (or add a level parameter to
LogRecoveredPanic), or rate-limit repeated panic logs per peer.