Context Propagation Inject Method Debugging

[paychex-ssmithrand]

Thank you to @ahayworth for answering my earlier question and getting me started on this path.

I've been developing a custom context propagator that will extract our custom trace headers and turn them into trace ids and span ids, use them internally, export them via OTLP to a collector, and then inject them as custom trace headers on the way out.

I've gotten to the point where my extract method is successfully finding the headers and converting them into ids, but I cannot seem to ascertain whether my inject method is being called. I have some print statements in it that seem to never execute, which makes me wonder if I'm returning something invalid or missing a step in extract. I've looked at the various other propagators included in the core api as well as contrib, and I seem to be doing everything the same. Code below:

def extract(carrier, context: Context.current, getter: Common::Propagation.rack_env_getter)
          trace_id = getter.get(carrier, PAYX_TXID_HEADER)
          span_id  = getter.get(carrier, PAYX_REQID_HEADER)

          return context unless trace_id
          
          trace_id = to_trace_id(trace_id.gsub('-',''))
          span_id  = to_span_id(span_id.gsub('-','').truncate(16,omission:""))

          span_context = Trace::SpanContext.new(
            trace_id: trace_id,
            span_id: span_id,
            tracestate: nil,
            remote: true
          )
          p span_context.valid? #Prints true
          span = OpenTelemetry::Trace.non_recording_span(span_context)
          OpenTelemetry::Trace.context_with_span(span, parent_context: context)
        end

def inject(carrier, context: Context.current, setter: Context::Propagation.text_map_setter)
          span_context = OpenTelemetry::Trace.current_span(context).context
          p span.context.valid? #Does not print at all
          return unless span_context.valid?

          p span_context.hex_trace_id()
          p span_context.hex_span_id()
          p carrier.keys()

          setter.set(carrier, PAYX_TXID_HEADER, span_context.hex_trace_id())
          setter.set(carrier, PAYX_REQID_HEADER, span_context.hex_span_id())
          nil
        end

[plantfansam]

@paychex-ssmithrand have you tried stepping through the code with a debugger? Are you sure you're using instrumentation gems that call inject somewhere?

Some maybe helpful background on propagators: the OpenTelemetry spec requires, and this library implements, a composite propagator. This runs each registered propagator whenever extract and inject are called. You can follow the code path starting from the Configurator. It is the responsibility of instrumentation to call inject — in the context of this library, that's invoked with OpenTelemetry.propagation.inject(carrier). See, for example, the HTTP client library.

[arielvalentin]

@paychex-ssmithrand Is it possible that your custom propagator is changing the sampling decision in some way? I see in the code snippet above you do not set the trace_flags attribute so it is setting it to DEFAULT¹, which currently means sampling is turned off².

Footnotes

1. https://github.com/open-telemetry/opentelemetry-ruby/blob/main/api/lib/opentelemetry/trace/span_context.rb#L27 ↩

2. https://github.com/open-telemetry/opentelemetry-ruby/blob/fcecf418eb67804c1bc6b1dfdf9ca71949f2f40f/api/lib/opentelemetry/trace/trace_flags.rb#L43 ↩

[paychex-ssmithrand]

@arielvalentin Thank you, that got me a bit closer. I see spans being exported to my collector now (makes sense as nothing was being sampled so nothing would be sent to it). However, I am still not seeing the inject method being called - and I still think that is due to Action_Pack instrumentation not calling inject, but rather doing some internal propagation work?

[arielvalentin]

I'm afraid I don't understand what you are asking.

Injecting headers should happen on outbound HTTP requests and responses. So you should only see inject being called in instrumentation for HTTP client libraries.

Your application will extract headers when it is the server. This happens in the Rack instrumentation.

Are you having trouble with propagating context using the Inject or continuing traces using Extract?

[ahayworth]

This sounds like you're building something in Rails, and maybe you're expecting to see your custom headers returned when you inspect the web requests in the Chrome dev tools, or something. Like @arielvalentin said, that's not what context propagation injection is actually about.

Context propagation extract is called when a server receives a request. It extracts the necessary headers so that it has the information it needs from the client to continue a trace.

Context propagation inject is called whenever a client sends a request. It injects the necessary headers so that the receiving server has the information it needs to continue a trace.

To test this: you could just write a script using the Net::HTTP instrumentation combined with your custom propagation, and all it needs to do is make a request to your Rails app. When you visualize the trace, you should be able to see the client (Net::HTTP) span as the logical parent of the server spans. If that relationship happens and the trace "looks right", you can presume that it's fully functional at that point. ❤️

---

Notably - none of our instrumentation calls inject when responding to a browser request (at least, none that I know of right now). Typically there's no reason for us to actually do that, because even if the browser happens to be doing OpenTelemetry tracing, it doesn't need or want to continue a trace using the server's span info; that would make further work on the client appear (in a trace) as though it was a logical child of the server's operation which isn't actually the case. 😄

[paychex-ssmithrand]

Sorry for the radio silence @arielvalentin and @ahayworth. Our in-house propagation libraries were built with the concept of adding response trace headers even though it is redundant as the information has been recorded as the request comes in. I understand now what is going on.

Things seem to be working correctly!

I am now on to converting baggage to span attributes so that the collector can see the additional contextual data that comes along via custom headers. Of course, if this is conceptually not correct, please do let me know.

[paychex-ssmithrand]

Quoting @arielvalentin and @ahayworth from the above thread as the answer:

Injecting headers should happen on outbound HTTP requests and responses. So you should only see inject being called in instrumentation for HTTP client libraries.
Your application will extract headers when it is the server. This happens in the Rack instrumentation.

This sounds like you're building something in Rails, and maybe you're expecting to see your custom headers returned when you inspect the web requests in the Chrome dev tools, or something. Like @arielvalentin said, that's not what context propagation injection is actually about.

Context propagation extract is called when a server receives a request. It extracts the necessary headers so that it has the information it needs from the client to continue a trace.

Context propagation inject is called whenever a client sends a request. It injects the necessary headers so that the receiving server has the information it needs to continue a trace.

To test this: you could just write a script using the Net::HTTP instrumentation combined with your custom propagation, and all it needs to do is make a request to your Rails app. When you visualize the trace, you should be able to see the client (Net::HTTP) span as the logical parent of the server spans. If that relationship happens and the trace "looks right", you can presume that it's fully functional at that point. ❤️

Notably - none of our instrumentation calls inject when responding to a browser request (at least, none that I know of right now). Typically there's no reason for us to actually do that, because even if the browser happens to be doing OpenTelemetry tracing, it doesn't need or want to continue a trace using the server's span info; that would make further work on the client appear (in a trace) as though it was a logical child of the server's operation which isn't actually the case. 😄