Lighthouse has a new layout. Prefer the old one? Return to the old layout, and switch back any time from the link at the top of each page.

This project is archived and is in readonly mode.

Strange behaviour in exception display

#4427

I spent a bunch of time tracking a strange baheviour in Rails 3 exception display. The problem doesn't show up in 2.3.5.
Here it is:

Step 1: Context

app/controllers/subitems_controller.rb

class SubitemsController < ApplicationController
  def index
    @subitems = Item.first.subitems
  end
end

app/views/subitems/index.html.erb

<%= @subitems %>
<%= Boum.new %>

result

As expected, this renders Action Controller: Exception caught in the browser with the following message uninitialized constant ActionView::CompiledTemplates::Boum, fine.

Step 2: Not displaying subitems

app/controllers/subitems_controller.rb

class SubitemsController < ApplicationController
  def index
    @subitems = Item.first.subitems
  end
end

app/views/subitems/index.html.erb

<%= Boum.new %>

result

This renders 500 Internal Server Error, weird.

Step 3: Getting sibitems directly, instead of going through the item has_many subitems association

app/controllers/subitems_controller.rb

class SubitemsController < ApplicationController
  def index
    @subitems = Subitem.all
  end
end

app/views/subitems/index.html.erb

<%= Boum.new %>

h4. result
Things back to normal: the exception is rendered correctly in the browser.

h3. Test configuration

OS X 10.5.8
Rails 3.0.0.beta3
Both 1.8.7 p249 & 1.9.1 p378

Am I wrong, or is it an unexpected behaviour?

PS
Sample app attached (in step1 state, rake db:migrate / rake db:seed).

Reported by Karl Alexandre · April 17th, 2010 @ 09:47 AM

State: resolved
Milestone: 3.0.2
Assigned to: Rohit Arondekar Rohit Arondekar
Importance: High

Activity

  1. Karl Alexandre
    Karl Alexandre
    • No changes were found…

    April 17th, 2010 @ 09:49 AM

  2. Karl Alexandre
  3. Santiago Pastorino
    Santiago Pastorino
    • Assigned user set to Santiago Pastorino

    Karl Alexandre, i have tried your application with the latest rails code from github and works as expected.
    Please get a fresh copy from github, generate the application copy your models, views, controllers, routes and try it again.
    Then we can close this issue.
    Thanks.

    April 22nd, 2010 @ 08:05 PM

  4. Karl Alexandre
    Karl Alexandre

    Santiago,

    I bundled edge rails and still have the problem somehow.
    The first request (step2) renders the exception, all the following render a 500.
    The log file for two requests is attached.

    Karl.

    April 22nd, 2010 @ 09:14 PM

  5. Karl Alexandre
  6. Santiago Pastorino
    Santiago Pastorino

    Karl, works for me tell me how you did your app.

    You need to have the lastest rails from github and run ruby DIR_WHERE_YOU_HAVE_RAILS_REPO/bin/rails myapp --dev

    And then start doing the routes, models, and all again.

    Let me know.

    April 22nd, 2010 @ 10:51 PM

  7. Karl Alexandre
    Karl Alexandre

    Santigo,

    Run this script and tell me the result on your side.

    Karl.

    April 23rd, 2010 @ 08:01 AM

  8. Santiago Pastorino
    Santiago Pastorino

    Ok i'm trying right now, try this one you.

    April 23rd, 2010 @ 02:24 PM

  9. Santiago Pastorino
    Santiago Pastorino

    Your patch doesn't apply cleanly on a fresh Rails edge generated app.
    But try my app.

    April 23rd, 2010 @ 02:27 PM

  10. Karl Alexandre
    Karl Alexandre
    • Tag changed from actiondispatch, activerecord, exception to activerecord rails3, actiondispatch, activerecord, exception

    Santiago,

    Sorry for late reply,

    In your app you have Subitems.all in the controller, it works ok with it.
    Now try Item.first.subitems , it fails on the second request for me.
    Strange thing is that Item.first.subitems.all works fine, but Item.first.subitems fails.

    yours,
    Karl.

    April 27th, 2010 @ 09:32 AM

  11. Steven Ringo
    Steven Ringo
    • Assigned user changed from Santiago Pastorino to Ryan Bigg

    Just tried this with the following configuration:

    ruby 1.9.1p378 (2010-01-10 revision 26273) [i386-darwin10.2.0]
    Rails 3.0.0.beta3

    Works as expected and yields:
    undefined method subitems' for nil:NilClass

    April 27th, 2010 @ 10:18 AM

  12. Karl Alexandre
    Karl Alexandre

    Steven,
    It seems you don't have the database populated with at least one item. Did you run rake db:seed ?

    April 27th, 2010 @ 11:12 AM

  13. Ryan Bigg
    Ryan Bigg

    I did this and I get:
    uninitialized constant ActionView::CompiledTemplates::Boum. No 500 page, just a standard white-and-grey error page.

    April 27th, 2010 @ 11:21 AM

  14. Karl Alexandre
    Karl Alexandre

    Ryan,
    The first request is always OK. Try two requests in a row, and tell me the result of the second one.

    I'm digging deeper and what I see now is that ActionDispatch::ShowExceptions::render_exception goes FAILSAFE while rendering this exception for the second time.

    April 27th, 2010 @ 12:06 PM

  15. Ryan Bigg
    Ryan Bigg

    Multiple requests works for me, I'm interested as to how you can replicate this issue.

    April 27th, 2010 @ 12:13 PM

  16. Anil Wadghule
    Anil Wadghule

    yeah it is an issue. See here http://pastie.org/937107. When you start server you get proper error page with exception. On second request you get "500 Internal Server Error"

    April 27th, 2010 @ 01:06 PM

  17. Karl Alexandre
    Karl Alexandre

    Anil,

    I don't get this exact trace, but that's the point.

    Two interresing points :
    - First, the association gets loaded even if not used (in my example), - Second, the exception fire two times as expected, but the middleware goes fail safe with can't dup nil class on the second rendering (may be something to do with template compiler ?)

    April 27th, 2010 @ 01:45 PM

  18. Karl Alexandre
    Karl Alexandre

    All,

    The cause of the problem is that _request_and_response.erb template inspects the current controller throught request.env["action_controller.instance"]

    In my example app this reference the @subitems instance variable.

    If I prevent this to happen by adding <%@request.env.delete("action_controller.instance")%> to _request_and_response.erb , everything goes fine.

    Why all this lead to a can't dup nil class in ActiveRecord::Base.scoped_methods (Cause of the 500) ? To be continued...

    April 27th, 2010 @ 03:20 PM

  19. Jeremy Kemper
    Jeremy Kemper
    • Milestone cleared.
    • State changed from new to open

    April 27th, 2010 @ 06:44 PM

  20. Dan Pickett
    Dan Pickett
    • Tag changed from activerecord rails3, actiondispatch, activerecord, exception to activerecord rails3, actiondispatch, activerecord, bugmash, exception

    Can a bugmasher reproduce this behavior?

    May 15th, 2010 @ 01:51 AM

  21. Rohit Arondekar
    Rohit Arondekar

    I too got a 500 Internal Server Error by following the steps provided by Karl.

    I created a gist of the rails server output => http://gist.github.com/401967 -- Note that I have demarcated the logs of the two requests. Before the " Started GET "/subitems/index" " of the second request a error is shown as follows:

    Error during failsafe response:
    ActionView::Template::Error (can't dup NilClass) in /home/rohit/.rvm/gems/ruby-1.9.2-head/gems/actionpack-3.0.0.beta3/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb:

    Also by switching to Subitem.all the 500 error doesn't appear.

    May 15th, 2010 @ 04:10 AM

  22. Rohit Arondekar
    Rohit Arondekar

    Forgot to mention my environment:
    Ubuntu 10.04
    ruby 1.9.2dev (2010-05-08 trunk 27665) [x86_64-linux]
    Rails 3.0.0.beta3

    May 15th, 2010 @ 05:19 AM

  23. Anil Wadghule
    Anil Wadghule

    verified

    See pasties for info about the logs

    https://gist.github.com/2cc2371975ade98b85e5
    http://pastie.org/937107

    Environment:
    Macbook Pro Snow Leopard
    ruby-1.8.7-p249 [ x86_64 ]
    Rails 3 master branch "a0621c1086165e4b3cff71b54f08a190851b6314"

    Attached is rails app with which this bug is reproducible.

    May 15th, 2010 @ 07:14 AM

  24. Gavin Stark
    Gavin Stark

    This is happening, I believe, because in ActiveRecord::Base

        def scoped_methods #:nodoc:
          key = :"#{self}_scoped_methods"
          Thread.current[key] = Thread.current[key].presence || self.default_scoping.dup
        end
    

    On the second request self.default_scoping is nil as opposed to []. This causes an exception trying to dup nil. However, I cannot see what is setting the default_scoping to nil

    May 15th, 2010 @ 10:20 PM

  25. Jonas Huckestein
    Jonas Huckestein

    I had the same problem when using Tyler Kovac's HyperBase with is a subclass of ActiveRecord::Base.

    default_scoping is defined as a class_inheritable_accessor in base.rb. It gets initialized in ActiveRecord::Base and HyperBase wasn't able to see the default value. Adding "self.default_scoping = self.superclass.default_scoping" to HyperBase resolved the situation. I'm not sure if that is a smart fix, though. It is my understanding that this is the intende behavior of class_inheritable_accessor.

    What I don't understand is why most ActiveRecord::Base subclasses to see the default value for default_Scoping (which is []). Can somebody from the team explain how that works?

    This problem was killing me, hope I could help a little bit.

    May 28th, 2010 @ 10:35 PM

  26. Rohit Arondekar
    Rohit Arondekar
    • Importance changed from to High

    I can't reproduce this on Rails 3 RC, can somebody else give a try?

    August 3rd, 2010 @ 08:27 AM

  27. Jeremy Kemper
  28. Len Smith
    Len Smith

    Can't reproduce on Safari, Chrome or Firefox on OSX, Rails 3.0.0 and ruby 1.9.2p0.

    September 14th, 2010 @ 12:16 AM

  29. Rohit Arondekar
    Rohit Arondekar
    • State changed from open to resolved

    I think this issue got resolved along the way. I'm going to go ahead and close. If anybody still faces this issue just leave a comment and I'll reopen it.

    September 14th, 2010 @ 04:23 AM

  30. Andrea Campi
    Andrea Campi
    • Assigned user changed from Ryan Bigg to Rohit Arondekar

    Just a reminder you said you would close this :)

    October 8th, 2010 @ 03:57 PM

  31. Rohit Arondekar
    Rohit Arondekar

    Andrea, the ticket is already closed as 'resolved'. :)

    October 9th, 2010 @ 01:37 AM

  32. Jeremy Kemper
  33. Jeff Kreeftmeijer
    Jeff Kreeftmeijer
    • Tag cleared.

    Automatic cleanup of spam.

    November 8th, 2010 @ 08:51 AM

  34. yoyogo
    yoyogo

    oh my!! i love you so much!!

    Thank you so much.
    Hermes Bags
    http://www.louisvuittonparty.com/
    Hermes Bags

    March 31st, 2011 @ 05:59 AM

  35. af001
    af001

    私の中で、総合評価のとっても低いアバアバクロホリスタークロ銀座店。アバクロは大好きなんですけどね。一昨日の東京駅付近での打ち合わせの後、散歩がてら久々に行ってきました。そしたらビックリ!相変わらアバクロず、踊っているだけの店員さんとかもいましたが、

    May 5th, 2011 @ 02:55 AM

  36. ssupreme11
    ssupreme11

    Its my first time to visit this site and as I was exploring I cant believe that this site was made up of a very informative articles that you should try to have compliment with so as what I am doing now I really love to look forward with more interesting information on this site..

    Regards,
    Dissertation Proposal

    May 10th, 2011 @ 10:29 PM