add busted_tracer middleware #16

HParker · 2016-09-21T06:15:06Z

Fixes #2

adds logging for use in a rails/rack app.

simeonwillbanks · 2016-09-23T13:26:11Z

README.md

@@ -162,6 +162,22 @@ $ ruby start_finish_trace.rb

 **Busted** includes an [example `dtrace` probe](/dtrace/probes/examples/method-cache-clear.d) for use on the command line or an application.  See the [probe](/dtrace/probes/examples/method-cache-clear.d) for usage.

+# Rails Usage


Please, let's make this a subheadline via ## Rails Usage, so it matches the rest of the file.

simeonwillbanks · 2016-09-23T13:34:42Z

test/middleware/busted_tracer.rb

@@ -0,0 +1,26 @@
+require "logger"


test/middleware/busted_tracer.rb is the same as lib/busted/middleware/busted_tracer.rb. Why must we copy the file into the test directory?

Thanks! I totally missed that I had the file twice.
That was some bad git hygiene on my part.

No worries 😄

after PR simeonwillbanks#15 merged, this is the only test that uses the old minitest test syntax. We can also eliminate some "ambiguous first argument; put parentheses or a space even after `/' operator" by adding parentheses after assert_equal methods in tests

The "coming soon" link in the readme now points to the rails docs. The Rails Usage header is now the proper "##" depth

simeonwillbanks · 2016-09-23T15:20:52Z

test/middleware_test.rb

+      middleware.call({})
+    end
+
+    assert_match(/methods=0 constants=0/, log.messages.last)


The method's name is test_it_logs_cache_invalidations, but we aren't asserting on "[Cache Invalidations]". Why don't we add "[Cache Invalidations]" to this tests and maybe the others?

HParker · 2016-09-23T17:02:58Z

lib/busted/profiler.rb

@@ -2,6 +2,7 @@
 require "busted/countable"
 require "busted/tracer"
 require "busted/traceable"
+require "busted/middleware/busted_tracer"


Oh, I realized that we probably don't need to require the middleware in all cases. Do you think it would be worth it try to load it dynamically?

What do you have in mind for dynamically loading?

HParker · 2016-10-01T22:42:47Z

@simeonwillbanks do you think you could take another look? I think I resolved everything we discussed.

simeonwillbanks · 2016-10-04T15:14:48Z

README.md

+In rails you can use the `BustedTracer` middleware to log the method and constant cache invalidations. You can configure BustedTracer using,
+
+```ruby
+config.middleware.insert_after(ActionDispatch::Static, BustedTracer)


Why don't we test BustedTracer comes before the rest of the middleware stack:

config.middleware.insert_before(0, BustedTracer)

Do you mean test if it works first in the middleware stack, or specifically require the middleware to be first in the stack?

@HParker My thoughts are config.middleware.insert_before 0 makes sure BustedTracer runs at the beginning of the stack.

Why did you suggest ActionDispatch::Static? I've got a Rails 5.0 app handy, and here's its out-of-the-box middleware stack.

~/Code/rails_5 ❯ rails --version Rails 5.0.1 ~/Code/rails_5 ❯ rake middleware Running via Spring preloader in process 63804 use Rack::Sendfile use ActionDispatch::Static use ActionDispatch::Executor use ActiveSupport::Cache::Strategy::LocalCache::Middleware use Rack::Runtime use Rack::MethodOverride use ActionDispatch::RequestId use Sprockets::Rails::QuietAssets use Rails::Rack::Logger use ActionDispatch::ShowExceptions use WebConsole::Middleware use ActionDispatch::DebugExceptions use ActionDispatch::RemoteIp use ActionDispatch::Reloader use ActionDispatch::Callbacks use ActiveRecord::Migration::CheckPending use ActionDispatch::Cookies use ActionDispatch::Session::CookieStore use ActionDispatch::Flash use Rack::Head use Rack::ConditionalGet use Rack::ETag run Rails5::Application.routes

simeonwillbanks · 2016-10-04T15:21:07Z

lib/busted/middleware/busted_tracer.rb

@@ -0,0 +1,26 @@
+require "logger"
+
+class BustedTracer


I looked at a few other middlewares, and they are using a different class name and file structure.

SecureHeaders::Middleware

BetterErrors::Middleware

RequestStore::Middleware

I think we should adopt this pattern.

Busted::Middleware

./lib/busted/middleware.rb

Thoughts @HParker ?

simeonwillbanks · 2016-10-04T15:27:46Z

@HParker have you tested the new middleware in a few Rails apps? We should test in at least one Rails 4 and one Rails 5 app.

Also, maybe we can spin up some vanilla Rails 4 and 5 apps then define some invalidations in application code. That way, we can test out middleware insertion and compare the expected log messages with actual log messages.

Thoughts?

HParker · 2016-10-05T01:45:43Z

I have only tested in a rails 5 app, though I think the middleware API is rack version specific not rails version specific right?

alepore · 2016-10-15T15:11:59Z

i'm using it on rails 4.1 and 4.2 and seems ok!

…rovide-middleware

HParker · 2016-11-09T03:02:48Z

@simeonwillbanks Let me know if theres anything else I can do to move this along.

Putting the middleware after the ActionDispatch::Static middleware assumes something about what you are trying to trace.

simeonwillbanks · 2017-08-25T17:55:24Z

@alepore Are you using the gem or the middleware in this Pull Request?

@HParker I tried out Busted and the middleware in a Rails 5.0.1 app, and Rails is causing unclear reports.

Here's Busted in a rails console:

❯ rails c
Running via Spring preloader in process 74873
Loading development environment (Rails 5.0.1)
WARN: couldn't load pry. `gem install pry`
>> Busted.start
=> true
>> def smoothie
>>   end
=> :smoothie
>> Busted.finish
=> {:invalidations=>{:method=>0, :constant=>0}}
>> RUBY_VERSION
=> "2.3.1"
>> Rails.version
=> "5.0.1"
>> exit

Maybe something with Spring preloader?

Here's Busted in irb:

❯ irb
Frame number: 0/4
[1] pry(main)> require 'busted'
true
[2] pry(main)> RUBY_VERSION
"2.3.1"
[3] pry(main)> Busted.start
true
[4] pry(main)> def smoothie
[4] pry(main)* end
:smoothie
[5] pry(main)> Busted.finish
{
    :invalidations => {
          :method => 1,
        :constant => 0
    }
}

I don't understand why the rails console session doesn't report a method cache invalidation.

In an app, I tried the middleware. I fiddled with insert_before and use. use felt nicer because log lines were tagged with a request ID.

config.middleware.use(Busted::Middleware)

class HomeController < ApplicationController
  class Hello

  end
  def index

  end
end

❯ rails s -e production
=> Booting Puma
=> Rails 5.0.1 application starting in production on http://0.0.0.0:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.7.1 (ruby 2.3.1-p112), codename: Snowy Sagebrush
* Min threads: 5, max threads: 5
* Environment: production
* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop

I, [2017-08-25T10:24:13.219601 #82611]  INFO -- : [2b782e81-895d-416a-bf5c-66ac61cdfd18] Started GET "/" for 127.0.0.1 at 2017-08-25 10:24:13 -0700
I, [2017-08-25T10:24:13.221760 #82611]  INFO -- : [2b782e81-895d-416a-bf5c-66ac61cdfd18] Processing by HomeController#index as HTML
I, [2017-08-25T10:24:13.229328 #82611]  INFO -- : [2b782e81-895d-416a-bf5c-66ac61cdfd18]   Rendering home/index.html.erb within layouts/application
I, [2017-08-25T10:24:13.229742 #82611]  INFO -- : [2b782e81-895d-416a-bf5c-66ac61cdfd18]   Rendered home/index.html.erb within layouts/application (0.3ms)
I, [2017-08-25T10:24:13.232409 #82611]  INFO -- : [2b782e81-895d-416a-bf5c-66ac61cdfd18] Completed 200 OK in 11ms (Views: 4.6ms)
I, [2017-08-25T10:24:13.232550 #82611]  INFO -- : [2b782e81-895d-416a-bf5c-66ac61cdfd18] [Cache Invalidations] methods=0 constants=25
I, [2017-08-25T10:24:20.447573 #82611]  INFO -- : [d0350e93-4f35-47e6-a446-f374345eda5c] Started GET "/" for 127.0.0.1 at 2017-08-25 10:24:20 -0700
I, [2017-08-25T10:24:20.448192 #82611]  INFO -- : [d0350e93-4f35-47e6-a446-f374345eda5c] Processing by HomeController#index as HTML
I, [2017-08-25T10:24:20.448952 #82611]  INFO -- : [d0350e93-4f35-47e6-a446-f374345eda5c]   Rendering home/index.html.erb within layouts/application
I, [2017-08-25T10:24:20.449102 #82611]  INFO -- : [d0350e93-4f35-47e6-a446-f374345eda5c]   Rendered home/index.html.erb within layouts/application (0.1ms)
I, [2017-08-25T10:24:20.449421 #82611]  INFO -- : [d0350e93-4f35-47e6-a446-f374345eda5c] Completed 200 OK in 1ms (Views: 0.7ms)
I, [2017-08-25T10:24:20.449573 #82611]  INFO -- : [d0350e93-4f35-47e6-a446-f374345eda5c] [Cache Invalidations] methods=0 constants=0

constants=25

Using Busted in the app worked as expected.

class HomeController < ApplicationController
  Busted.start
  class Hello
    def wat
      puts 'wat'
    end
  end
  report = Busted.finish
  Rails.logger.info "[Cache Invalidations From Inside App] methods=#{report[:invalidations][:method]} constants=#{report[:invalidations][:constant]}"
  def index

  end
end

I, [2017-08-25T10:31:37.763701 #85692]  INFO -- : [Cache Invalidations From Inside App] methods=0 constants=1
I, [2017-08-25T10:31:40.972717 #85692]  INFO -- : [3aa49c88-36b7-4934-be66-8288d2f38b6d] Started GET "/" for 127.0.0.1 at 2017-08-25 10:31:40 -0700
I, [2017-08-25T10:31:40.974271 #85692]  INFO -- : [3aa49c88-36b7-4934-be66-8288d2f38b6d] Processing by HomeController#index as HTML
I, [2017-08-25T10:31:40.982846 #85692]  INFO -- : [3aa49c88-36b7-4934-be66-8288d2f38b6d]   Rendering home/index.html.erb within layouts/application
I, [2017-08-25T10:31:40.983252 #85692]  INFO -- : [3aa49c88-36b7-4934-be66-8288d2f38b6d]   Rendered home/index.html.erb within layouts/application (0.3ms)
I, [2017-08-25T10:31:40.985770 #85692]  INFO -- : [3aa49c88-36b7-4934-be66-8288d2f38b6d] Completed 200 OK in 11ms (Views: 4.5ms)
I, [2017-08-25T10:31:40.985914 #85692]  INFO -- : [3aa49c88-36b7-4934-be66-8288d2f38b6d] [Cache Invalidations] methods=0 constants=25
I, [2017-08-25T10:32:05.094020 #85692]  INFO -- : [207d7e1d-1435-4a14-9902-63cdf90d846b] Started GET "/" for 127.0.0.1 at 2017-08-25 10:32:05 -0700
I, [2017-08-25T10:32:05.094684 #85692]  INFO -- : [207d7e1d-1435-4a14-9902-63cdf90d846b] Processing by HomeController#index as HTML
I, [2017-08-25T10:32:05.095420 #85692]  INFO -- : [207d7e1d-1435-4a14-9902-63cdf90d846b]   Rendering home/index.html.erb within layouts/application
I, [2017-08-25T10:32:05.095531 #85692]  INFO -- : [207d7e1d-1435-4a14-9902-63cdf90d846b]   Rendered home/index.html.erb within layouts/application (0.0ms)
I, [2017-08-25T10:32:05.095815 #85692]  INFO -- : [207d7e1d-1435-4a14-9902-63cdf90d846b] Completed 200 OK in 1ms (Views: 0.6ms)
I, [2017-08-25T10:32:05.095910 #85692]  INFO -- : [207d7e1d-1435-4a14-9902-63cdf90d846b] [Cache Invalidations] methods=0 constants=0

[Cache Invalidations From Inside App] methods=0 constants=1

Overall, it feels like we might go down a rabbit hole understanding how the middleware is working within Rails. To respect your time (now and in the future when Rails changes), I don't think we should go down that rabbit hole, and we should keep Busted focused. Thoughts?

HParker · 2017-08-25T18:26:28Z

I agree the numbers are confusing. If we end up providing a tool like this, it probably will need to change with rails version, this tool does not need to care about rails, so we should probably keep that part separate from this gem no matter what. I'll close and see if I can find a way to get sane numbers from rails another time and place.

simeonwillbanks · 2017-08-25T18:31:44Z

@HParker Sounds good and agreed.

Thank you very much for your contributions and patience! 🍻

add busted_tracer middleware

652cfd3

simeonwillbanks reviewed Sep 23, 2016

View reviewed changes

HParker added 4 commits September 23, 2016 07:11

Merge branch 'master' into provide-middleware

8ccfdd3

delete accidental test tracer

d0fa561

update test style

457f8ad

after PR simeonwillbanks#15 merged, this is the only test that uses the old minitest test syntax. We can also eliminate some "ambiguous first argument; put parentheses or a space even after `/' operator" by adding parentheses after assert_equal methods in tests

update README [ci skip]

26c3f0c

The "coming soon" link in the readme now points to the rails docs. The Rails Usage header is now the proper "##" depth

simeonwillbanks reviewed Sep 23, 2016

View reviewed changes

make log tests more specific

9478952

HParker commented Sep 23, 2016

View reviewed changes

simeonwillbanks reviewed Oct 4, 2016

View reviewed changes

simeonwillbanks closed this Oct 4, 2016

simeonwillbanks reopened this Oct 4, 2016

HParker added 2 commits October 16, 2016 20:58

rename middleware

f5e3bfc

Merge branch 'provide-middleware' of github.com:HParker/busted into p…

8bf20a0

…rovide-middleware

HParker and others added 2 commits August 25, 2017 09:34

Make middleware explicitly first

2c47312

Putting the middleware after the ActionDispatch::Static middleware assumes something about what you are trying to trace.

BustedTracer renamed to Busted::Middleware

2756c36

HParker closed this Aug 25, 2017

simeonwillbanks mentioned this pull request Aug 25, 2017

Add Rails Profiler #2

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add busted_tracer middleware #16

add busted_tracer middleware #16

HParker commented Sep 21, 2016

simeonwillbanks Sep 23, 2016

simeonwillbanks Sep 23, 2016

simeonwillbanks Sep 23, 2016

HParker Sep 23, 2016

simeonwillbanks Sep 23, 2016

simeonwillbanks Sep 23, 2016

HParker Sep 23, 2016

simeonwillbanks Oct 4, 2016

HParker commented Oct 1, 2016

simeonwillbanks Oct 4, 2016

HParker Oct 5, 2016

simeonwillbanks Aug 25, 2017

simeonwillbanks Oct 4, 2016

HParker Oct 5, 2016

simeonwillbanks commented Oct 4, 2016

HParker commented Oct 5, 2016

alepore commented Oct 15, 2016

HParker commented Nov 9, 2016

simeonwillbanks commented Aug 25, 2017

HParker commented Aug 25, 2017

simeonwillbanks commented Aug 25, 2017

		@@ -162,6 +162,22 @@ $ ruby start_finish_trace.rb

		Busted includes an [example `dtrace` probe](/dtrace/probes/examples/method-cache-clear.d) for use on the command line or an application. See the [probe](/dtrace/probes/examples/method-cache-clear.d) for usage.

		# Rails Usage

add busted_tracer middleware #16

add busted_tracer middleware #16

Conversation

HParker commented Sep 21, 2016

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

HParker commented Oct 1, 2016

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

simeonwillbanks commented Oct 4, 2016

HParker commented Oct 5, 2016

alepore commented Oct 15, 2016

HParker commented Nov 9, 2016

simeonwillbanks commented Aug 25, 2017

HParker commented Aug 25, 2017

simeonwillbanks commented Aug 25, 2017