Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

if current is nil, just skip it #68

Conversation

@everplays
Copy link
Contributor

commented Mar 18, 2014

fixes undefined method `discard' for nil:NilClass.

here's the complete error that I got:

NoMethodError at /en/front_office/parks/31:Landgoed-Hommelheide
undefined method `discard' for nil:NilClass
Ruby    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-mini-profiler-0.9.1/lib/mini_profiler/profiler.rb: in call, line 307
Web     GET localhost/en/front_office/parks/31:Landgoed-Hommelheide
Jump to:

    GET
    POST
    Cookies
    ENV

Traceback (innermost first)

    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-mini-profiler-0.9.1/lib/mini_profiler/profiler.rb: in call
        skip_it = !current.nil? ? current.discard : true...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/railties-4.0.3/lib/rails/engine.rb: in call
        app.call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/railties-4.0.3/lib/rails/application.rb: in call
        super(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/railties-4.0.3/lib/rails/railtie/configurable.rb: in method_missing
        instance.send(*args, &block)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-1.5.2/lib/rack/lint.rb: in _call
        status, headers, @body = @app.call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-1.5.2/lib/rack/lint.rb: in call
        dup._call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-1.5.2/lib/rack/showexceptions.rb: in call
        @app.call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-1.5.2/lib/rack/commonlogger.rb: in call
        status, header, body = @app.call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-1.5.2/lib/rack/chunked.rb: in call
        status, headers, body = @app.call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/rack-1.5.2/lib/rack/content_length.rb: in call
        status, headers, body = @app.call(env)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/unicorn-4.8.0/lib/unicorn/http_server.rb: in process_client
        status, headers, body = @app.call(env = @request.read(client))...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/unicorn-4.8.0/lib/unicorn/http_server.rb: in worker_loop
        process_client(client)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/newrelic_rpm-3.7.3.199/lib/new_relic/agent/instrumentation/unicorn_instrumentation.rb: in call
        old_worker_loop.bind(self).call(worker)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/newrelic_rpm-3.7.3.199/lib/new_relic/agent/instrumentation/unicorn_instrumentation.rb: in block (4 levels) in <top (required)>
        old_worker_loop.bind(self).call(worker)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/unicorn-4.8.0/lib/unicorn/http_server.rb: in spawn_missing_workers
        worker_loop(worker)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/unicorn-4.8.0/lib/unicorn/http_server.rb: in start
        spawn_missing_workers...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/gems/unicorn-4.8.0/bin/unicorn: in <top (required)>
        Unicorn::HttpServer.new(app, options).start.join...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/bin/unicorn: in load
        load Gem.bin_path('unicorn', 'unicorn', version)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/bin/unicorn: in <main>
        load Gem.bin_path('unicorn', 'unicorn', version)...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/bin/ruby_executable_hooks: in eval
        eval File.read($0), binding, $0...
    /home/behrooz/.rvm/gems/ruby-2.0.0-p353@bookingexperts/bin/ruby_executable_hooks: in <main>
        eval File.read($0), binding, $0...

after getting the error, tried to remove tmp/miniprofiler/ directory which didn't help. However, this change fixed it.

if current is nil, just skip it
fixes undefined method `discard' for nil:NilClass
@SamSaffron

This comment has been minimized.

Copy link
Member

commented Mar 19, 2014

hmm, I want to dig a bit deeper, how can current be nil there?

@socjopata

This comment has been minimized.

Copy link

commented Apr 2, 2014

Not sure if this is related but I just got !! Unexpected error while processing request: undefined methoddiscard' for nil:NilClass` in the server logs, with no stacktrace. The page fails to load, and instead a blank page is presented with just 'Internal server error'.

If you would like me to create it's own ticket for this or provide some more details - let me know.

@julik

This comment has been minimized.

Copy link
Contributor

commented Apr 15, 2014

I am observing the same problem. What I've done so far, is sprinkled the following line all over the "call" method to see what the values are throughout. The line looks like this:

      puts "#{object_id} - #{__LINE__} #{current.object_id} - #{self.current.object_id}"

Note that I am explicitly looking at the reader method AND a potential local variable because initially I suspected both to be defined. When you use ensure/rescue a variable definition can bleed "up" in the code and become defined earlier than you expect from the lexical scope, so this was my initial suspicion. However, upon closer inspection in a Rails 3.2 app on Ruby 2.1.1 here is what I see printed (both on Thin and Webrick):

70366348674680 - 241 8 - 8
70366348674680 - 243 70366321512460 - 70366321512460
70366348674680 - 245 70366321512460 - 70366321512460
70366348674680 - 265 70366321512460 - 70366321512460
70366348674680 - 274 70366321512460 - 70366321512460
70366348674680 - 277 70366321512460 - 70366321512460
70366348675020 - 241 70366321512460 - 70366321512460
70366348675020 - 243 70366321522920 - 70366321522920
70366348675020 - 245 70366321522920 - 70366321522920
70366348675020 - 265 70366321522920 - 70366321522920
70366348675020 - 274 70366321522920 - 70366321522920
70366348675020 - 277 70366321522920 - 70366321522920
70366348675020 - 309 70366321522920 - 70366321522920
70366348675020 - 311 70366321522920 - 70366321522920
70366348675020 - 314 70366321522920 - 70366321522920
70366348674680 - 309 8 - 8
70366348674680 - 311 8 - 8
70366348674680 - 314 8 - 8

As you can see there is one middleware object allocated (70366348674680) - and it initializes current, as desired. Than around the time we are on line 277 in ...680 the second middleware object gets initialized - and it as well gets called. This object jumps sets current as well, to an object with id ...2920, and seemingly runs to completion.

From there on, the ..680 middleware object triws to get at it again and in it's ensure block current is already nil.

I suspect a race condition invloving Thread.current (which is now per-fiber not per-thread) and ensures. Or there are two Profilers created per thread where you actually want one. I get this trace with a single request via curl - that single request does not fetch any extra resources, so in theory there should only be one call()

Here a file with liberal print statements for reference:

https://gist.github.com/julik/dacec8a034b2625f6a8e

@SamSaffron

This comment has been minimized.

Copy link
Member

commented Apr 15, 2014

can you print Thread.current.object_id with your debug statement. and print
when middleware starts / finishes.

On Tue, Apr 15, 2014 at 9:52 PM, Julik Tarkhanov
notifications@github.comwrote:

I am observing the same problem. What I've done so far, is sprinkled the
following line all over the "call" method to see what the values are
throughout. The line looks like this:

  puts "#{object_id} - #{__LINE__} #{current.object_id} - #{self.current.object_id}"

Note that I am explicitly looking at the reader method AND a potential
local variable because initially I suspected both to be defined. When you
use ensure/rescue a variable definition can bleed "up" in the code and
become defined earlier than you expect from the lexical scope, so this was
my initial suspicion. However, upon closer inspection in a Rails 3.2 app on
Ruby 2.1.1 here is what I see printed (both on Thin and Webrick):

70366348674680 - 241 8 - 8
70366348674680 - 243 70366321512460 - 70366321512460
70366348674680 - 245 70366321512460 - 70366321512460
70366348674680 - 265 70366321512460 - 70366321512460
70366348674680 - 274 70366321512460 - 70366321512460
70366348674680 - 277 70366321512460 - 70366321512460
70366348675020 - 241 70366321512460 - 70366321512460
70366348675020 - 243 70366321522920 - 70366321522920
70366348675020 - 245 70366321522920 - 70366321522920
70366348675020 - 265 70366321522920 - 70366321522920
70366348675020 - 274 70366321522920 - 70366321522920
70366348675020 - 277 70366321522920 - 70366321522920
70366348675020 - 309 70366321522920 - 70366321522920
70366348675020 - 311 70366321522920 - 70366321522920
70366348675020 - 314 70366321522920 - 70366321522920
70366348674680 - 309 8 - 8
70366348674680 - 311 8 - 8
70366348674680 - 314 8 - 8

As you can see there is one middleware object allocated (70366348674680) -
and it initializes current, as desired. Than around the time we are on line
277 in ...680 the second middleware object gets initialized - and it as
well gets called. This object jumps sets current as well, to an object with
id ...2920, and seemingly runs to completion.

From there on, the ..680 middleware object triws to get at it again and in
it's ensure block current is already nil.

I suspect a race condition invloving Thread.current (which is not
per-fiber not per-thread) and ensures.

An alternative might be that the current gets unset by a different request
while the current request is still busy, and that happens in the same
thread / fiber.

Here a file with liberal print statements for reference:

https://gist.github.com/julik/dacec8a034b2625f6a8e


Reply to this email directly or view it on GitHubhttps://github.com//pull/68#issuecomment-40472739
.

@julik

This comment has been minimized.

Copy link
Contributor

commented Apr 15, 2014

And it happens because the profiler is initialized twice. The guide stipulates to put the following into the Gemfile:

gem 'rack-mini-profiler'

and the following into the Rails initializer:

if Rails.env == 'development'
  require 'rack-mini-profiler'
  # initialization is skipped so trigger it
  Rack::MiniProfilerRails.initialize!(Rails.application)
end

This requires the gem twice, and some initialization also runs twice. If I replace the line for the Gemfile with:

gem 'rack-mini-profiler', :require => false

there is only one Profiler in the middleware stack and the error stops occurring. If I let the Gemfile do the require, and remove it from the initializer

if Rails.env == 'development'
  # initialization is skipped so trigger it
  Rack::MiniProfilerRails.initialize!(Rails.application)
end

the problem reappears.

@SamSaffron

This comment has been minimized.

Copy link
Member

commented Apr 15, 2014

Double initialisation is a huge no-no, can you submit a PR to fix what you
find confusing about the guide?

On Tue, Apr 15, 2014 at 10:07 PM, Julik Tarkhanov
notifications@github.comwrote:

And it happens because the profiler is initialized twice. The guide
stipulates to put the following into the Gemfile:

gem 'rack-mini-profiler'

and the following into the Rails initializer:

if Rails.env == 'development'
require 'rack-mini-profiler'

initialization is skipped so trigger it

Rack::MiniProfilerRails.initialize!(Rails.application)
end

This requires the gem twice, and some initialization also runs twice. If I
replace the line for the Gemfile with:

gem 'rack-mini-profiler', :require => false

there is only one Profiler in the middleware stack and the error stops
occurring. If I let the Gemfile do the require, and remove
it in the initializer

if Rails.env == 'development'

initialization is skipped so trigger it

Rack::MiniProfilerRails.initialize!(Rails.application)
end

the problem reappears.


Reply to this email directly or view it on GitHubhttps://github.com//pull/68#issuecomment-40473832
.

@julik

This comment has been minimized.

Copy link
Contributor

commented Apr 15, 2014

I can try, but this should have some "idiot proof" protection built-in...

@SamSaffron

This comment has been minimized.

Copy link
Member

commented Apr 15, 2014

Sure, PR for idiot proofing ? if initialize is called twice hell should
break loose.

On Tue, Apr 15, 2014 at 10:25 PM, Julik Tarkhanov
notifications@github.comwrote:

I can try, but this should have some "idiot proof" protection built-in...


Reply to this email directly or view it on GitHubhttps://github.com//pull/68#issuecomment-40475092
.

@julik

This comment has been minimized.

Copy link
Contributor

commented Apr 15, 2014

see below ;-) even though this is user error I think failing early on it is a better course of action.

@everplays everplays closed this Aug 12, 2014

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.