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

Remove irrelevant frames from panic traces #774

Merged
merged 1 commit into from
Feb 19, 2025

Conversation

bgentry
Copy link
Contributor

@bgentry bgentry commented Feb 19, 2025

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
Copy link
Contributor

@brandur brandur left a comment

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.

@@ -131,7 +131,7 @@ func (e *JobExecutor) execute(ctx context.Context) (res *jobExecutorResult) {
)

res = &jobExecutorResult{
PanicTrace: string(debug.Stack()),
PanicTrace: captureStackTraceSkipFrames(4),
Copy link
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
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
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
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
10 checks passed
@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