feat: Use Rack::Events for instrumentation #342

arielvalentin · 2023-02-18T02:39:54Z

This is an alternate implementation of the Rack instrumentation that leverages the Rack::Events API instead of a customRack::Middleware.

Why am I suggesting we change this instrumentation? At GitHub we leverage Rack::BodyProxy to write Rack Request logs after the request is complete, however Rack span is already finished and its related Context has already been detached. This means we are not able to correlate request logs to our traces.

The advantage of using Rack::Events is that handlers are triggered during difference stages of a request, including for deferred operations like Rack::BodyProxy, as opposed to middlewares who only are invoked inline.

The disadvantage of this API is that it makes managing the request more difficult and we have to track the Context positions to detach in the Rack::Env.

This implementation will be released along side the existing instrumtation to give users the option to use the middleware instead of the Rack::Events handler until we are able to run this in some of our heavy production workloads.

Other noteworthy things:

The http.proxy span has been converted to a Span Event and ignores the record_frontend_span option
There are no new events added that we brainstormed in this discussion: feat: Use Rack::Events for instrumentation #342 (comment)
All configuration options for this middleware that required special processing/registration were moved into the Rack::Instrumentation.install
The Rack event now includes the time it takes to write the response to the socket.
Sinatra 1.4 depends on Rack 1 so we must support both Rack Middleware and Events unless we choose to drop support for it.

Fixes #341 Related DataDog/dd-trace-rb#1746

fbogsany · 2023-02-21T19:01:15Z

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb

+          # @note does nothing if the span is a non-recording span
+          # @param [Rack::Request] The current HTTP request
+          # @param [Rack::Response] The current HTTP response
+          def on_finish(request, response)


It might also be nice to add on_send and record a span event for "sent first byte" or something similar. It is really nice to know, from a perf analysis perspective, when the application has finalized the response and the remaining work is "out of our hands".

An interesting philosophical question: when should we consider the server span "finished"? When application processing is complete or when the response has been completely written to the socket? I think the current middleware implementation is effectively equivalent to "when application processing is complete", before anything has been written to the socket.

It might also be nice to add on_send and record a span event for "sent first byte" or something similar. It is really nice to know, from a perf analysis perspective, when the application has finalized the response and the remaining work is "out of our hands".

I like this idea a lot! I will add it to my todo list.

An interesting philosophical question: when should we consider the server span "finished"? When application processing is complete or when the response has been completely written to the socket? I think the current middleware implementation is effectively equivalent to "when application processing is complete", before anything has been written to the socket.

💭 I'm not sure. I lean towards after the middleware has completed writing the response but does that make it asymmetric from when it's processing the incoming request? I'm not entirely certain.

Going to hold off adding other events until I get this initial implementation merged.

I am also going to stick with on_finish, i.e. after the response has been written to the socket and the Rack::BufferedResponse is closed.

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb

This is an alternate implementation of the Rack instrumentation that leverages the [`Rack::Events` API](https://www.rubydoc.info/gems/rack/Rack/Events) instead of a custom`Rack::Middleware`. Why am I suggesting we change this instrumentation? At GitHub we leverage `Rack::BodyProxy` to write Rack Request logs after the request is complete, however Rack span is already finished and its related `Context` has already been detached. This means we are not able to correlate request logs to our traces. The advantage of using `Rack::Events` is that handlers are triggered during difference stages of a request, including for deferred operations like [`Rack::BodyProxy`](https://www.rubydoc.info/gems/rack/Rack/BodyProxy), as opposed to middlewares who _only_ are invoked inline. The disadvantage of this API is that it makes managing the request more difficult and we have to track the Context positions to detach in the `Rack::Env`. This implementation will be released along side the existing instrumtation to give users the option to use the middleware instead of the `Rack::Events` handler until we are able to run this in some of our heavy production workloads. Fixes open-telemetry#341 Related DataDog/dd-trace-rb#1746

…ash when it encounters errors

arielvalentin · 2023-03-19T14:09:58Z

Tests are failing for combination of rack >= 2.2 and rack test 2.1

arielvalentin · 2023-03-19T15:12:01Z

I have opened an issue with rack-test rack/rack-test#335

Hopefully I will be able to dig in something soon and see what is going on.

arielvalentin · 2023-03-19T18:22:51Z

jeremyevans set me straight. The test case setup was wrong.

fbogsany · 2023-03-20T16:17:41Z

instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb

+        # This option is only valid for applicaitons using Rack 2.0 or greater
+        option :use_rack_events,          default: false, validate: :boolean
+
+        # Temporary Helper for Sinatra and ActionPack middleware to use during installation


What's the long term plan (you may have answered this elsewhere)?

This configuration setting and helper will exist until...

We drop support for Sinatra versions that require Rack 1.x

A future release that makes the Event Handler the default way for users to instrument their applications

fbogsany · 2023-03-20T16:19:16Z

instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb

          require_relative 'middlewares/tracer_middleware'
        end
+
+        def config_options(user_config)


@robertlaurin is config_options intended to be overridden? It looks OK to me, but I don't think we've explicitly called it out as OK for instrumentation to override.

@fbogsany @robertlaurin Is this a blocker for merging and releasing the event-based implementation?

fbogsany · 2023-03-20T16:22:58Z

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/tracer_middleware.rb

@@ -6,8 +6,6 @@

 require 'opentelemetry/trace/status'

-require_relative '../util/queue_time'
-
 module OpenTelemetry
  module Instrumentation
    module Rack


Any reason not to update this to use the config[:allowed_rack_request_headers] and config[:allowed_rack_response_headers] precomputed in the Instrumentation class?

I was worried about changing too many things at once in this PR.

I am certainly amenable to removing the duplication here.

fbogsany · 2023-03-20T16:25:11Z

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb

+          def record_frontend_span?
+            config[:record_frontend_span] == true
+          end
+
+          def untraced_endpoints
+            config[:untraced_endpoints]
+          end
+
+          def untraced_requests
+            config[:untraced_requests]
+          end
+
+          def url_quantization
+            config[:url_quantization]
+          end
+
+          def response_propagators
+            config[:response_propagators]
+          end
+
+          def allowed_request_headers
+            config[:allowed_rack_request_headers]
+          end
+
+          def allowed_response_headers
+            config[:allowed_rack_response_headers]
+          end


Is there any reason not to cache all these config options in instance variables?

The existing instrumentation supports being able to inject the middleware and then initializing the SDK afterwards.

Using instance variables made it so the instance in the middleware had stale values and did not reflect the values after the instrumentation was installed so I didn't have a choice but to look them up.

My understanding is that caching config option values in instance variables is not a blocker to adding the event-based implementation. 👍🏻

I think caching (I'm assuming "via memoization" here) is something we could consider doing in a future release if/when the middleware-based implementation is removed.

robbkidd

It hangs together, new behavior is behind a feature flag config option, old behavior works in the handful of Racky test apps I have.

# in a Gemfile
gem 'opentelemetry-instrumentation-rack', git: 'https://github.com/open-telemetry/opentelemetry-ruby-contrib', glob: 'instrumentation/*/*.gemspec'

I'd like to see the instrumentation's options appear documented in the gem's README, but (1) of the existing options, only url_quantization is mentioned so this is not really a hard criteria for this new option and (2) I can be the change I want to see in the world (I'll open a PR updating the README).

arielvalentin · 2023-04-05T19:23:47Z

OOOOOOOOPPPPPPPPPPPPSSSSSS I had set this to auto-merge by accident. I hope that is not a problem.

fbogsany reviewed Feb 21, 2023

View reviewed changes

arielvalentin commented Feb 22, 2023

View reviewed changes

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb Outdated Show resolved Hide resolved

arielvalentin commented Feb 28, 2023

View reviewed changes

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb Show resolved Hide resolved

arielvalentin commented Feb 28, 2023

View reviewed changes

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb Outdated Show resolved Hide resolved

arielvalentin commented Feb 28, 2023

View reviewed changes

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb Outdated Show resolved Hide resolved

arielvalentin added 9 commits March 1, 2023 19:58

squash: additional feature parity

24ea563

squash: add allowed response headers

06e4fe3

squash: url quantization

725b722

squash: Now with new Lemon Scented response headers

8a2dd29

squash: we are now at parity

752a739

squash: use instrumetation config

aba820e

squash: Use declarative config options

999594e

squash: fix bad refactoring

5261676

arielvalentin force-pushed the use-events-instead-of-middleware branch from 2272df2 to 5261676 Compare March 2, 2023 01:59

arielvalentin added 6 commits March 1, 2023 20:28

convert proxy span to an event

e66a188

refactor: move configurations to instrumentation install

700f58f

squash: add test converage

7154ec7

squash: make response headers a little more resilient

69e60eb

squash: Ensures event middleware will not cause the application to cr…

006cea0

…ash when it encounters errors

squash: fix linter error

12c0e0f

arielvalentin marked this pull request as ready for review March 2, 2023 12:38

arielvalentin requested review from mwear, robertlaurin, dazuma, ahayworth, plantfansam and robbkidd as code owners March 2, 2023 12:38

arielvalentin requested review from fbogsany and ericmustin March 2, 2023 13:53

arielvalentin marked this pull request as ready for review March 6, 2023 14:25

arielvalentin and others added 6 commits March 7, 2023 08:34

Merge branch 'main' into use-events-instead-of-middleware

ce02dce

Merge branch 'main' into use-events-instead-of-middleware

0e50bba

Merge branch 'main' into use-events-instead-of-middleware

26c5a30

Merge branch 'main' into use-events-instead-of-middleware

f134ec2

Merge branch 'main' into use-events-instead-of-middleware

16a4896

fix: bad merge

205cd66

arielvalentin mentioned this pull request Mar 19, 2023

Rack >= 2.2.2 tests skip Rack::Events#on_finish rack/rack-test#335

Closed

arielvalentin added 2 commits March 19, 2023 13:05

fix: invalid responses in test case

e9e837e

squash: Added a few more test cases

0a961a1

arielvalentin enabled auto-merge (squash) March 19, 2023 22:59

fbogsany reviewed Mar 20, 2023

View reviewed changes

arielvalentin requested a review from fbogsany March 23, 2023 15:07

Merge branch 'main' into use-events-instead-of-middleware

19d7c79

robbkidd self-assigned this Mar 31, 2023

robbkidd approved these changes Apr 5, 2023

View reviewed changes

Merge branch 'main' into use-events-instead-of-middleware

e88b745

arielvalentin merged commit c179d3b into open-telemetry:main Apr 5, 2023

arielvalentin deleted the use-events-instead-of-middleware branch April 5, 2023 19:23

KaoruDev mentioned this pull request May 21, 2023

Streaming responses causes spans to be orphaned #474

Open

robertlaurin mentioned this pull request Jun 28, 2023

Allow out-of-band, async upload functionality Shopify/app_profiler#80

Merged

github-actions bot mentioned this pull request Jan 5, 2024

chore: release main #794

Closed

mtomov mentioned this pull request Jan 11, 2024

Sentry.set_user should work with OpenTelemetry getsentry/sentry-ruby#2171

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: Use Rack::Events for instrumentation #342

feat: Use Rack::Events for instrumentation #342

arielvalentin commented Feb 18, 2023 •

edited

Loading

fbogsany Feb 21, 2023

arielvalentin Feb 21, 2023

arielvalentin Mar 2, 2023

arielvalentin commented Mar 19, 2023

arielvalentin commented Mar 19, 2023

arielvalentin commented Mar 19, 2023

fbogsany Mar 20, 2023

arielvalentin Mar 20, 2023

fbogsany Mar 20, 2023

robbkidd Apr 5, 2023

fbogsany Mar 20, 2023

arielvalentin Mar 20, 2023

fbogsany Mar 20, 2023

arielvalentin Mar 20, 2023

robbkidd Apr 5, 2023

robbkidd left a comment •

edited

Loading

arielvalentin commented Apr 5, 2023

feat: Use Rack::Events for instrumentation #342

feat: Use Rack::Events for instrumentation #342

Conversation

arielvalentin commented Feb 18, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arielvalentin commented Mar 19, 2023

arielvalentin commented Mar 19, 2023

arielvalentin commented Mar 19, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

robbkidd left a comment • edited Loading

Choose a reason for hiding this comment

arielvalentin commented Apr 5, 2023

arielvalentin commented Feb 18, 2023 •

edited

Loading

robbkidd left a comment •

edited

Loading