Add Rack instrumentation #166

duonoid · 2020-01-14T01:04:20Z

Overview

Adds rack instrumentation adapter implementation, ported from existing dd-trace-rb functionality.

rack instrumentation is required by rails instrumentation, which does not exist yet.

Details

adds a working example, runnable via docker-compose, e.g.,

docker-compose run --rm ex-adapter-rack
bash-5.0$ ruby trace_demonstration.rb

adds functionality to trace 'front-end' request (queue time) and retain middleware names
QueueTimeimplementation is directly from dd-trace-rb
config options include:retain_middleware_names, :allowed_response_headers, :allowed_request_headers

I have a few more comments. We have options now that Tracer#in_span records and reraises exceptions. I left a comment showing how we can take advantage of it. There are also quite a few comments in the source that were useful for review, but should probably be removed for the final version. If you don't mind take a look through them and make a judgement call about what should stay, or go.

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

mwear · 2020-02-21T02:02:10Z

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

+
+          private
+
+          def create_request_span(env, context)


If you use the alternative call above, this method won't exactly be necessary.

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

mwear · 2020-02-21T02:04:04Z

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

+
+          # return Context with the frontend span as the current span
+          def create_frontend_span(env, extracted_context)
+            # NOTE: get_request_start may return nil


This is probably a useful comment, but we might be able to loose the following notes.

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

mwear · 2020-02-21T02:06:18Z

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

+          # Note: if a middleware catches an Exception without re raising,
+          # the Exception cannot be recorded here.
+          def record_and_reraise_error(error, request_span:)
+            request_span.record_error(error)


Span#record_error sets the status for us now. If you use the alternate call (that uses in_span) we won't need this method. If we keep it, it doesn't need to set the status.

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

* note that order of finished spans is now swapped

mwear

This is getting there. I found a couple of issues with nil attributes that you'll find in the comments. One other issue I found is that when this is used along with Sinatra we get a NameError because the reference to Rack::Utils needs to be written as ::Rack::Utils since since we have a Rack constant in OpenTelemetry::Adapters now.

The line that needs updating is here: https://github.com/open-telemetry/opentelemetry-ruby/blob/master/adapters/sinatra/lib/opentelemetry/adapters/sinatra/middlewares/tracer_middleware.rb#L46

Example stacktrace:

NameError: uninitialized constant OpenTelemetry::Adapters::Rack::Utils
	/Users/matthewwear/Repos/opentelemetry-ruby/adapters/sinatra/lib/opentelemetry/adapters/sinatra/middlewares/tracer_middleware.rb:46:in `trace_response'
	/Users/matthewwear/Repos/opentelemetry-ruby/adapters/sinatra/lib/opentelemetry/adapters/sinatra/middlewares/tracer_middleware.rb:26:in `block (2 levels) in call'
	/Users/matthewwear/Repos/opentelemetry-ruby/adapters/sinatra/lib/opentelemetry/adapters/sinatra/middlewares/tracer_middleware.rb:26:in `tap'
	/Users/matthewwear/Repos/opentelemetry-ruby/adapters/sinatra/lib/opentelemetry/adapters/sinatra/middlewares/tracer_middleware.rb:26:in `block in call'
	/Users/matthewwear/Repos/opentelemetry-ruby/api/lib/opentelemetry/trace/tracer.rb:51:in `block in in_span'
	/Users/matthewwear/Repos/opentelemetry-ruby/api/lib/opentelemetry/trace/tracer.rb:66:in `block in with_span'
	/Users/matthewwear/Repos/opentelemetry-ruby/api/lib/opentelemetry/context.rb:59:in `with_value'
	/Users/matthewwear/Repos/opentelemetry-ruby/api/lib/opentelemetry/trace/tracer.rb:66:in `with_span'
	/Users/matthewwear/Repos/opentelemetry-ruby/api/lib/opentelemetry/trace/tracer.rb:51:in `in_span'
	/Users/matthewwear/Repos/opentelemetry-ruby/adapters/sinatra/lib/opentelemetry/adapters/sinatra/middlewares/tracer_middleware.rb:18:in `call'
...

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

Co-Authored-By: Matthew Wear <[email protected]>

* value is potentially nil, which is not a valid attribute value * also 'service' is not an official semantic convention and will probably come from the application resource in the future

mwear

@duonoid: thank you so much for all your hard work on this!

mwear · 2020-02-27T01:23:28Z

Last call for comments. It'd be nice to merge this tomorrow after the SIG meeting.

fbogsany · 2020-02-28T16:20:19Z

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

+            end
+          ensure
+            finish_span(frontend_context)
+          end


This seems pretty convoluted and incorrect. If I understand correctly, with the "frontend" span enabled, we'll end up with 2 spans nested like:

name: http_server.queue start_timestamp: T end_timestamp: T+D kind: server attributes: - start_time: request_start_time children: - name: $REQUEST_URI start_timestamp: T-ish end_timestamp: T+D-ish kind: server ...

There are several problems here:

The duration of the 2 spans is about the same, so the queue time is only represented in an attribute of the outer span. It is more useful to create the http_server.queue span with start_timestamp: request_start_time, which will more accurately represent the LB request duration as the span's duration.

Both spans are marked as kind: server, which is logically incorrect and would be reported as so by some vendors' trace quality reports. This is supposed to represent time between a proxy/LB receiving a request and the service handling it, there has been chatter about representing this with something like kind: proxy (Span.Kind.LOAD_BALANCER (PROXY/SIDECAR) opentelemetry-specification#51 and Clarify the interpretation of SpanKind opentelemetry-specification#337).

For analysis backends deriving SLIs from trace data, it is possible they may count requests twice if both spans are kind: server.

Calling the frontend span http_server.queue is inaccurate - it actually represents (almost) the entire request processing time from the perspective of the LB/proxy.

Alternatives:

Rename the frontend span to http_server.proxy or similar. Change the kind of the request span to internal if the frontend span is present.

Use a single span with start_timestamp: request_start_time, kind: :server and add a timed event for the service start time (i.e. "now").

Create both spans as children of the extracted_context, with the frontend span having start_timestamp: request_start_time, end_timestamp: now and the request span having start_timestamp: now. This allows the frontend span to represent queuing time only.

Create 2 spans for the frontend: a kind: :server and a kind: :client with the same start time and duration but a different resource. Specifying a different resource is not supported by the API presently.

My vote would be for option 1 or 2. The original datadog instrumentation did have span.kind = proxy. internal would work for now and we can change it to proxy when and if it gets added.

As a side issue, I think we are going to have problems with nested server spans. Currently Sinatra will set its span kind as server. Using Rack with Sinatra will result in nesting of server spans. We will need to come up with a way to resolve this issue as a user could use Sinatra instrumentation without Rack instrumentation, and that would be what you want.

The same is true for client spans with Faraday + net http.

I've updated, using Option 1.

I'm happy with this. @fbogsany WDYT?

* request_span.kind is :internal if frontend_span is present * future: change request_span :kind to ':proxy' if/when it gets added to spec

…ion--67 # Conflicts: # .circleci/config.yml # Rakefile # docker-compose.yml

duonoid · 2020-02-28T19:23:59Z

I've resolved the merge conflicts.

mwear · 2020-02-28T20:58:47Z

The conflicts are back.

…ion--67 # Conflicts: # .circleci/config.yml # Rakefile # docker-compose.yml

duonoid · 2020-02-28T21:14:47Z

conflicts: resolved. 😄

fbogsany · 2020-03-05T17:15:17Z

I approved. I'll still extract my comment to an issue, since I think the spec will have to address this at some point, and we may need to revisit. This is 👍 for now tho.

This configuration option sets a rack environment variable that isn't used in the instrumentation or its dependencies. dd-trace-rb used this option to set the span name to the Rack application Name: https://github.com/DataDog/dd-trace-rb/blob/d76de947d66fe50f5ac6c7a6016ebbfa5c0de986/lib/datadog/tracing/contrib/rack/middlewares.rb#L158 It looks like some of the functionality was ported over but applying it to the span name was never completed: open-telemetry/opentelemetry-ruby#166

duonoid added 8 commits January 13, 2020 16:44

rack: Add Gemfile, gemspec, version

508b8df

* rack-test: "simple testing API for Rack apps" * fix: "Could not find rake-12.3.3 in any of the sources"

Add Rakefile

367c78c

e.g., $ bundle exec rake test

tests: Add test_helper

6f5c5e1

Add example: trace_demonstration

3ed377c

e.g., $ docker-compose run --rm ex-adapter-rack bash-5.0$ ruby trace_demonstration.rb

Add QueueTime

acb435c

* from dd-trace-rb * translate spec to minitest

Add TracerMiddleware

384e331

* use dup._call env pattern * RE: thread safety: "... easiest and most efficient way to do this is to dup the middleware object that is created in runtime." * do we need 'quantization' now?

Add Adapters::Rack::Adapter

6a6fd0a

* retain middleware names (feature exists in dd-trace-rb)

Add Adapters::Rack

16e8d32

fbogsany reviewed Jan 21, 2020

View reviewed changes

adapters/rack/Gemfile Outdated Show resolved Hide resolved

fbogsany reviewed Jan 21, 2020

View reviewed changes

adapters/rack/lib/opentelemetry/adapters/rack/util/queue_time.rb Outdated Show resolved Hide resolved

duonoid added 2 commits January 21, 2020 12:10

Update to 2020 copyright

4da0f61

Initialize 'now' later

b62e0fa

mwear reviewed Jan 21, 2020

View reviewed changes

duonoid and others added 2 commits January 21, 2020 17:21

Merge branch 'master' into rack-instrumentation--67

59b5791

Adapt to Instrumentation Auto Installer interface

5e2be00

* PR #164

duonoid commented Jan 22, 2020

View reviewed changes

duonoid and others added 14 commits January 22, 2020 15:38

Fix example to use updated Instrumentation Auto Installer

423397a

* verified by running via, e.g., $ docker-compose run --rm ex-adapter-rack bash-5.0$ bundle bash-5.0$ ruby trace_demonstration.rb Expected: console output of span data

Handle errors by setting span.status, leave a TODO and rescue clause

0be8aff

Allow config[:quantization]

14b1198

* to allow for lower cardinality span names

Remove optional parent context extraction

9f0e2d8

* defeats purpose of opentelemetry, which *is* distributed tracing

Resolve 'http.base_url' TODO

fb1bf71

* add 'http.target'

Resolve 'resource name' TODO

ea061d3

* it seems that dd-trace-rb's 'span.resource' is the same as 'span.name', at least in this case

Resolve 'http.route' TODO

242b403

* in sinatra, data is available via env['sinatra.route'].split.last, but otherwise, doesn't seem to be readily available

Note: missing 'span.set_error()' for now

c3b9319

Resolve FrontendSpan TODOs

b110cf1

* resolve 'http_server.queue' TODO * span kind of 'proxy' is not defined, yet

Optimize allowed_request_headers

4cdca21

* reduce string allocations * TIL: a nested 'before' block doesn't run before *each* test, but the top/first 'before' block does. (weird)

Optimize allowed_response_headers()

ba86941

* prevent unneeded string and object allocation * once a header key is found, add it to the list of response headers to search for

Optimize return of EMPTY_HASH frozen constant

e328a7c

Refactor to avoid using dup._call(env)

6544839

* avoid using instance variables

Merge branch 'master' into rack-instrumentation--67

5604391

duonoid added 2 commits February 19, 2020 15:15

Adjust error handling according to #184

fb3a242

mwear reviewed Feb 21, 2020

View reviewed changes

duonoid and others added 3 commits February 21, 2020 16:34

Rewrite to utilize in_span

e763e21

* note that order of finished spans is now swapped

Reduce comments that were more useful in development/review

e5d15c6

Merge branch 'master' into rack-instrumentation--67

313f576

mwear requested changes Feb 25, 2020

View reviewed changes

mwear reviewed Feb 25, 2020

View reviewed changes

adapters/rack/lib/opentelemetry/adapters/rack/middlewares/tracer_middleware.rb Outdated Show resolved Hide resolved

duonoid and others added 4 commits February 25, 2020 09:34

Update http.host to use HTTP_HOST or 'unknown'

12b6b58

Co-Authored-By: Matthew Wear <[email protected]>

Update request_start_time to be number, not timestamp

bb3b9c2

Co-Authored-By: Matthew Wear <[email protected]>

Remove request_span comment

bcf940f

Remove 'service' attribute when creating frontend span

cc14c64

* value is potentially nil, which is not a valid attribute value * also 'service' is not an official semantic convention and will probably come from the application resource in the future

duonoid mentioned this pull request Feb 25, 2020

Fix ::Rack::Utils namespace resolution #192

Merged

Merge branch 'master' into rack-instrumentation--67

16079fa

mwear approved these changes Feb 26, 2020

View reviewed changes

fbogsany reviewed Feb 28, 2020

View reviewed changes

duonoid and others added 3 commits February 28, 2020 10:25

Change frontend_span to 'http_server.proxy', make request_span :internal

80b2c2d

* request_span.kind is :internal if frontend_span is present * future: change request_span :kind to ':proxy' if/when it gets added to spec

Merge branch 'master' into rack-instrumentation--67

85bf829

Merge remote-tracking branch 'upstream/master' into rack-instrumentat…

37c9f55

…ion--67 # Conflicts: # .circleci/config.yml # Rakefile # docker-compose.yml

Merge remote-tracking branch 'upstream/master' into rack-instrumentat…

d3443e3

…ion--67 # Conflicts: # .circleci/config.yml # Rakefile # docker-compose.yml

fbogsany approved these changes Mar 5, 2020

View reviewed changes

fbogsany merged commit c53e44d into open-telemetry:master Mar 5, 2020

arielvalentin mentioned this pull request Feb 28, 2023

feat!: Remove retain_middleware_names Rack Option open-telemetry/opentelemetry-ruby-contrib#356

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add Rack instrumentation #166

Add Rack instrumentation #166

duonoid commented Jan 14, 2020 •

edited

Loading

mwear left a comment

mwear Jan 21, 2020

duonoid Jan 25, 2020

duonoid Jan 22, 2020

mwear left a comment

mwear Feb 21, 2020

mwear Feb 21, 2020

mwear Feb 21, 2020

mwear left a comment

mwear left a comment

mwear commented Feb 27, 2020

fbogsany Feb 28, 2020

mwear Feb 28, 2020 •

edited

Loading

duonoid Feb 28, 2020

mwear Feb 28, 2020

duonoid commented Feb 28, 2020

mwear commented Feb 28, 2020

duonoid commented Feb 28, 2020

fbogsany commented Mar 5, 2020

+                        end
+                        def allowed_response_header_names
+                          Array(config[:allowed_response_headers])

+                        end
+                        def full_http_request_url
+                          # NOTE: dd-trace-rb has implemented 'quantization'? (which lowers url cardinality)

Add Rack instrumentation #166

Add Rack instrumentation #166

Conversation

duonoid commented Jan 14, 2020 • edited Loading

Overview

Details

Related

mwear left a 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

mwear left a 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

mwear left a comment

Choose a reason for hiding this comment

mwear left a comment

Choose a reason for hiding this comment

mwear commented Feb 27, 2020

Choose a reason for hiding this comment

mwear Feb 28, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

duonoid commented Feb 28, 2020

mwear commented Feb 28, 2020

duonoid commented Feb 28, 2020

fbogsany commented Mar 5, 2020

duonoid commented Jan 14, 2020 •

edited

Loading

mwear Feb 28, 2020 •

edited

Loading