From 86c8c5b38a570495c10d90005f3a2b4e4dfcebb7 Mon Sep 17 00:00:00 2001 From: Blake Gentry Date: Tue, 18 Feb 2025 20:53:57 -0600 Subject: [PATCH] remove irrelevant frames from panic traces 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. --- CHANGELOG.md | 2 ++ internal/jobexecutor/job_executor.go | 32 ++++++++++++++++++++-- internal/jobexecutor/job_executor_test.go | 33 +++++++++++++++++++++-- 3 files changed, 63 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1b78f57e..f2c4386a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 Finally, the implementation was refactored so that it uses the _real_ `river.Client` insert path, and also uses the same job execution path as real execution. This minimizes the potential for differences in behavior between testing and real execution. [PR #766](https://github.com/riverqueue/river/pull/766). +- 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. [PR #774](https://github.com/riverqueue/river/pull/774). + ### Fixed - Fix error message on unsuccessful client subscribe that erroneously referred to "Workers" not configured. [PR #771](https://github.com/riverqueue/river/pull/771). diff --git a/internal/jobexecutor/job_executor.go b/internal/jobexecutor/job_executor.go index 85b26152..97c3ae0a 100644 --- a/internal/jobexecutor/job_executor.go +++ b/internal/jobexecutor/job_executor.go @@ -6,7 +6,7 @@ import ( "errors" "fmt" "log/slog" - "runtime/debug" + "runtime" "time" "github.com/riverqueue/river/internal/execution" @@ -131,7 +131,13 @@ func (e *JobExecutor) execute(ctx context.Context) (res *jobExecutorResult) { ) res = &jobExecutorResult{ - PanicTrace: string(debug.Stack()), + // Skip the first 4 frames which are: + // + // 1. The `runtime.Callers` function. + // 2. The `captureStackTraceSkipFrames` function. + // 3. The current recovery defer function. + // 4. The `JobExecutor.execute` method working the job. + PanicTrace: captureStackTraceSkipFrames(4), PanicVal: recovery, } } @@ -325,3 +331,25 @@ func (e *JobExecutor) reportError(ctx context.Context, res *jobExecutorResult) { e.Logger.ErrorContext(ctx, e.Name+": Failed to report error for job", logAttrs...) } } + +// captureStackTrace returns a formatted stack trace string starting after +// skipping the specified number of frames. The skip parameter should be +// adjusted so that frames you want to hide (like the ones generated by the +// tracing functions themselves) are excluded. +func captureStackTraceSkipFrames(skip int) string { + // Allocate room for up to 100 callers; adjust as needed. + pcs := make([]uintptr, 100) + // Skip the specified number of frames. + n := runtime.Callers(skip, pcs) + frames := runtime.CallersFrames(pcs[:n]) + + var stackTrace string + for { + frame, more := frames.Next() + stackTrace += fmt.Sprintf("%s\n\t%s:%d\n", frame.Function, frame.File, frame.Line) + if !more { + break + } + } + return stackTrace +} diff --git a/internal/jobexecutor/job_executor_test.go b/internal/jobexecutor/job_executor_test.go index 0191baeb..6f08b151 100644 --- a/internal/jobexecutor/job_executor_test.go +++ b/internal/jobexecutor/job_executor_test.go @@ -3,6 +3,7 @@ package jobexecutor import ( "context" "errors" + "strings" "testing" "time" @@ -573,10 +574,30 @@ func TestJobExecutor_Execute(t *testing.T) { executor, bundle := setup(t) - executor.WorkUnit = newWorkUnitFactoryWithCustomRetry(func() error { panic("panic val") }, nil).MakeUnit(bundle.jobRow) + // Add a middleware so we can verify it's in the trace too: + executor.GlobalMiddleware = []rivertype.WorkerMiddleware{ + &testMiddleware{ + work: func(ctx context.Context, job *rivertype.JobRow, next func(context.Context) error) error { + return next(ctx) + }, + }, + } + + executor.WorkUnit = newWorkUnitFactoryWithCustomRetry(func() error { + panic("panic val") + }, nil).MakeUnit(bundle.jobRow) bundle.errorHandler.HandlePanicFunc = func(ctx context.Context, job *rivertype.JobRow, panicVal any, trace string) *ErrorHandlerResult { require.Equal(t, "panic val", panicVal) - require.Contains(t, trace, "runtime/debug.Stack()\n") + require.NotContains(t, trace, "runtime/debug.Stack()\n") + require.Contains(t, trace, "(*testMiddleware).Work") + // Ensure that the first frame (i.e. the file and line info) corresponds + // to the code that raised the panic. This ensures we've stripped out + // irrelevant frames like the ones from the runtime package which + // generated the trace, or the panic rescuing code. + lines := strings.Split(trace, "\n") + require.GreaterOrEqual(t, len(lines), 2, "expected at least one frame in the stack trace") + firstFrame := lines[1] // this line contains the file and line of the panic origin + require.Contains(t, firstFrame, "job_executor_test.go") return nil } @@ -704,3 +725,11 @@ func TestJobExecutor_Execute(t *testing.T) { require.Empty(t, job.Errors) }) } + +type testMiddleware struct { + work func(ctx context.Context, job *rivertype.JobRow, next func(context.Context) error) error +} + +func (m *testMiddleware) Work(ctx context.Context, job *rivertype.JobRow, next func(context.Context) error) error { + return m.work(ctx, job, next) +}