How to trace a panic in a go routine when the panic causes the context to be done

user_6129842 0
Viewed 285

I have a goroutine that is created when an inbound request comes in, and this is tracing with Opentelemetry:

        qsSpan.AddEvent("does this print? yes it does")
        go func(natsContext context.Context, nr *NewRequest) {
            defer func() {
                if panicked := recover(); panicked != nil {
                    err = fmt.Errorf("this doesn't print")
                    qsSpan.RecordError(err) // IF PANIC, HOW DO I USE qsSPAN HERE??
                    qsSpan.SetStatus(codes.Error, err.Error())
                }
            }()
            natsContext = callDatabase(natsContext, *nr) // HERE IS WHERE PANIC ORIGINATES
            defer wg.Done()
            defer func() { responseChannel <- *msg }()
            defer natsContext.Done()
            defer qsSpan.End()
        }(natsContext, nr)

I'd like to record an error on qsSpan when it panics, but I can't because the context dies

I'm forcing a panic on calldatabase with:

func callDatabase(ctx context.Context, request NewRequest) context.Context {
    var callDatabaseSpan trace.Span
    ctx, callDatabaseSpan = otel.Tracer("").Start(ctx, "callDatabase")
    defer callDatabaseSpan.End()

    minTime := 2.0
    maxTime := 3.0

    time.Sleep(time.Second * (time.Duration(minTime + rand.Float64()*(maxTime-minTime)))) // simulate db doing something
    callDatabaseSpan.AddEvent(fmt.Sprintf("refreshCount: %d %s %s %s\n", request.RefreshCount, request.DbQueryToRun, request.Requestid, time.Now().String()[:24]))

    panicVar := []string{"a", "b"}

    _ = panicVar[2] // FORCE PANIC HERE

    return ctx
}

I believe the issue is to do with my context being killed when calldatabase causes a panic, so the trace is lost. But I want to use the span created when the request comes in, and record the panic as an error there, instead of having to initialise a new span for the panic

EDIT:

I don't want to have to do this (which works), I want to use the qSpan:

        qsSpan.AddEvent("does this print? yes it does")
        go func(natsContext context.Context, nr *NewRequest) {
            defer func() {
                if panicked := recover(); panicked != nil {
                    ctxPanic := context.Background()
                    var pSpan trace.Span
                    ctxPanic, pSpan = otel.Tracer("").Start(ctxPanic, "panic") // INITIALISING NEW SPAN FOR PANIC WORKS, BUT I WANT TO USE qsSPAN TO TRACE PANIC ORIGIN
                    err := fmt.Errorf("calling calldatabase caused panic")
                    pSpan.RecordError(err)
                    pSpan.SetStatus(codes.Error, err.Error())
                    pSpan.End()
                    ctxPanic.Done()
                }
            }()
            natsContext = callDatabase(natsContext, *nr)
            defer wg.Done()
            defer func() { responseChannel <- *msg }()
            defer natsContext.Done()
            defer qsSpan.End()
        }(natsContext, nr)
opentracing goroutine go concurrency trace
1 Answers

Thanks to @SDJ for giving me the idea on how to fix this

I needed to create a span inside the routine that handles the database call (calldatabase), and then use that to record the error/panic. So create a middle span between the inbound request routine, and inside the routine that processes the request

        go func(natsContext context.Context, nr *NewRequest) {
            var hsSpan trace.Span
            natsContext, hsSpan = otel.Tracer("").Start(natsContext, "handlerequest") // CREATE THE SPAN HERE
            defer func() {
                if panicked := recover(); panicked != nil {
                    err := fmt.Errorf("calling calldatabase caused panic") // RECORD PANIC USING SPAN CREATED IN THIS ROUTINE
                    hsSpan.RecordError(err)
                    hsSpan.SetStatus(codes.Error, err.Error())
                    response = err.Error()
                    msg.Respond([]byte(response))
                } else {
                  func() { responseChannel <- *msg }() // IF NO PANIC SIGNAL THAT callDatabase DONE WHEN ROUTINE FINISHES
                }
            }()
            natsContext = callDatabase(natsContext, *nr) // CONTEXT PASSED AND RETURNED TO CONTINUE TRACING callDatabase FUNCTION
            defer wg.Done()
            defer natsContext.Done()
            defer hsSpan.End()
        }(natsContext, nr)

So now I have a trace from the request, from processing the request, and linked to those if there's a panic so I can identify the origin of the request that triggered a panic

user_61298420
Related