spans finished before response filter runs

[abuchanan-airbyte]

Expected Behavior

@ResponseFilter method can record to spans.

Actual Behaviour

Spans in @ResponseFilter methods showed isRecording=false (or a current span could not be found).

Steps To Reproduce

I had some telemetry being recorded in a request+response filter. Here's a simplified version of what I was doing:

@ServerFilter("/api/**")
class TracingServerFilter(...) {
  @RequestFilter
  fun traceRequest(req: HttpRequest<*>) {
       logger.info { "Span recording=${Span.current().isRecording}" }
    ... build some attributes
  }

  @ResponseFilter
  fun traceResponse(
    req: HttpRequest<*>,
    resp: HttpResponse<*>,
    throwable: Throwable?,
  ) {
   ... record attributes to current span
   logger.info { "Span recording=${Span.current().isRecording}" }
  }
}

The full code is here.

What I found was that the span was finished before traceResponse ran. I tried various methods of adding explicit ordering, such as implementing Ordering and using ServerFilterPhase.TRACING.after() and also using @Ordering and using hard-coded values. Nothing seemed to work, although I'm not sure I exhausted all possibilities.

Note that the span was started before traceRequest (so traceRequest could add record attributes, but traceResponse could not).

What did work was using HttpServerFilter instead of the newer, recommended request/response filter methods.

Environment Information

Micronaut 4.9

Example Application

No response

Version

4.9.0

[graemerocher]

could you provide an example that reproduces the issue?

[abuchanan-airbyte]

Hm, I thought my example in steps to reproduce of a request + response filter would be what you need. I'm happy to provide a better example, but can you tell me what's missing from that? Thanks