Skip to content

Remove irrelevant frames from panic traces - #774

Merged
bgentry merged 1 commit into
masterfrom
bg-better-panic-stack-traces
Feb 19, 2025
Merged

Remove irrelevant frames from panic traces#774
bgentry merged 1 commit into
masterfrom
bg-better-panic-stack-traces

Conversation

@bgentry

@bgentry bgentry commented Feb 19, 2025

Copy link
Copy Markdown
Contributor

While testing the rivertest.Worker, I realized the panic traces we're sending to the panic handler have initial frames that reflect the code that actually generates the trace, rather than starting with the user's code that actually panicked:

--- FAIL: TestChargeCreditCard (0.00s)
    --- FAIL: TestChargeCreditCard/Success (7.33s)
        logger.go:256: time=2025-02-18T20:27:37.080-06:00 level=ERROR msg="JobExecutor: panic recovery; possible bug with Worker" job_id=8374 kind=ChargeCreditCard panic_val="runtime error: invalid memory address or nil pointer dereference"
        logger.go:256: time=2025-02-18T20:27:37.081-06:00 level=ERROR msg="JobExecutor: Job panicked" error="runtime error: invalid memory address or nil pointer dereference" job_id=8374 job_kind=ChargeCreditCard
        worker.go:184: panic: runtime error: invalid memory address or nil pointer dereference
            goroutine 36 [running]:
            runtime/debug.Stack()
            	/opt/homebrew/Cellar/go/1.24.0/libexec/src/runtime/debug/stack.go:26 +0x64
            github.com/riverqueue/river/internal/jobexecutor.(*JobExecutor).execute.func1()
            	/Users/bgentry/River/river/internal/jobexecutor/job_executor.go:134 +0x380
            panic({0x1035d3c40?, 0x103c0f530?})
            	/opt/homebrew/Cellar/go/1.24.0/libexec/src/runtime/panic.go:787 +0xf0
            github.com/riverqueue/riverdemo/worker.(*SyntheticBaseWorker).syntheticSleepOrError(0x0, {0x1036c44c0, 0x14000056380}, {0x1036bb5e0, 0x140000b0320})
            	/Users/bgentry/River/riverdemo/worker/synthetic_base_job.go:22 +0x50
            github.com/riverqueue/riverdemo/worker.(*ChargeCreditCard).Work(0x1400000c090, {0x1036c44c0, 0x14000056380}, 0x1400004a310)
            	/Users/bgentry/River/riverdemo/worker/charge_credit_card.go:33 +0x19c
            github.com/riverqueue/river/rivertest.(*wrapperWorkUnit[...]).Work(0x1036c4320, {0x1036c44c0, 0x140000562a0})
            	/Users/bgentry/River/river/rivertest/worker.go:281 +0x60
            github.com/riverqueue/river/internal/jobexecutor.(*JobExecutor).execute(0x140000f0000, {0x1036c44c0, 0x140000562a0})
            	/Users/bgentry/River/river/internal/jobexecutor/job_executor.go:158 +0x3f8
            github.com/riverqueue/river/internal/jobexecutor.(*JobExecutor).Execute(0x140000f0000, {0x1036c4450, 0x140000a81e0})

To improve this, I adjusted the panic stack traces to filter out irrelevant frames like the ones generated by the runtime package that constructed the trace, or River's internal rescuing code. This makes the first panic frame reflect the actual panic origin for easier debugging. The unit test now ensures that the first frame is actually from the test file instead of stdlib runtime code.

@bgentry
bgentry requested a review from brandur February 19, 2025 02:57
@bgentry
bgentry force-pushed the bg-better-panic-stack-traces branch from 836d3cc to d047c48 Compare February 19, 2025 02:58
@bgentry bgentry changed the title remove irrelevant frames from panic traces Remove irrelevant frames from panic traces Feb 19, 2025

@brandur brandur left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice. Yeah, this should make these things a lot easier to read.


res = &jobExecutorResult{
PanicTrace: string(debug.Stack()),
PanicTrace: captureStackTraceSkipFrames(4),

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oof, it's good there's a test for this because it'd be pretty shaky otherwise. The raw number "4" probably merits a comment.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added a comment to explain and further improved test coverage, thanks

var stackTrace string
for {
frame, more := frames.Next()
stackTrace += fmt.Sprintf("%s\n\t%s:%d\n", frame.Function, frame.File, frame.Line)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I assume the formatting comes from what debug.Stack() would be doing? A little unfortunate that we have to format it manually here.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Adjusted panic stack traces to filter out irrelevant frames like the
ones generated by the runtime package that constructed the trace, or
River's internal rescuing code. This makes the first panic frame reflect
the actual panic origin for easier debugging.
@bgentry
bgentry force-pushed the bg-better-panic-stack-traces branch from d047c48 to 86c8c5b Compare February 19, 2025 16:42
@bgentry
bgentry merged commit 23408d1 into master Feb 19, 2025
@bgentry
bgentry deleted the bg-better-panic-stack-traces branch February 19, 2025 16:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants