[#JRUBY-2945] incorrect error stack trace since rev #7457. Make debugging Ruby code much harder sometimes. REGRESSION - jira.codehaus.org

JRuby

incorrect error stack trace since rev #7457. Make debugging Ruby code much harder sometimes. REGRESSION

Created: 22/Aug/08 07:34 PM Updated: 09/Feb/09 11:03 AM

Component/s:

Interpreter

Affects Version/s:

JRuby 1.1.4

Fix Version/s:

None

Time Tracking:

Not Specified

Environment:

Linux, Java 6

Description

« Hide

Let's take that example taken from a real Rails 2.1 app were I had a raise opinion.inspect statement somewhere inside a file called app/sweepers/opinions_sweeper.rb. So I was actually raising the error myself but had not clue what was going one because of the incorrect log:

Here is the stck with JRuby after rev #7457:

RuntimeError (#<Opinion id: 254, user_id: 0, topic_id: 85, own_summary: "no", own_text: "", own_url: "", cached_score: 0.0, cached_pool_priority: 0, cached_debt_counter: 0, created_at: "2008-08-22 22:08:23", updated_at: "2008-08-22 22:08:23", cached_level1: nil, cached_level2: nil, cached_tmp_debt_counter: 0, ip_code: 2130706433>):
/vendor/rails/activerecord/lib/active_record/transactions.rb:127:in `rollback_active_record_state!'
/vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save_with_transactions'
/app/controllers/opinions_controller.rb:73:in `create'
/vendor/rails/actionpack/lib/action_controller/mime_responds.rb:106:in `call'
/vendor/rails/actionpack/lib/action_controller/mime_responds.rb:106:in `respond_to'
/app/controllers/opinions_controller.rb:72:in `create'

Now, the same error running MRI or a previous JRuby version:

RuntimeError (#<Opinion id: 255, user_id: 0, topic_id: 86, own_summary: "my op", own_text: "", own_url: "", cached_score: 0.0, cached_pool_priority: 0, cached_debt_counter: 0, created_at: "2008-08-23 00:23:33", updated_at: "2008-08-23 00:23:33", cached_level1: nil, cached_level2: nil, cached_tmp_debt_counter: 0, ip_code: 2130706433>):
/app/sweepers/opinions_sweeper.rb:21:in `expire_cache_for'
/app/sweepers/opinions_sweeper.rb:8:in `after_create'
/vendor/rails/activerecord/lib/active_record/observer.rb:171:in `send'
/vendor/rails/activerecord/lib/active_record/observer.rb:171:in `update'
/usr/lib/ruby/1.8/observer.rb:185:in `notify_observers'
/usr/lib/ruby/1.8/observer.rb:184:in `each'
/usr/lib/ruby/1.8/observer.rb:184:in `notify_observers'
/vendor/rails/activerecord/lib/active_record/callbacks.rb:309:in `notify'
/vendor/rails/activerecord/lib/active_record/callbacks.rb:302:in `callback'
/vendor/rails/activerecord/lib/active_record/callbacks.rb:221:in `create_without_timestamps'
/vendor/rails/activerecord/lib/active_record/timestamp.rb:29:in `create'
/vendor/rails/activerecord/lib/active_record/base.rb:2464:in `create_or_update_without_callbacks'
/vendor/rails/activerecord/lib/active_record/callbacks.rb:207:in `create_or_update'
/vendor/rails/activerecord/lib/active_record/base.rb:2192:in `save_without_validation'
/vendor/rails/activerecord/lib/active_record/validations.rb:901:in `save_without_dirty'
/vendor/rails/activerecord/lib/active_record/dirty.rb:75:in `save_without_transactions'
/vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save'
/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:66:in `transaction'
/vendor/rails/activerecord/lib/active_record/transactions.rb:79:in `transaction'
/vendor/rails/activerecord/lib/active_record/transactions.rb:98:in `transaction'
/vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save'
/vendor/rails/activerecord/lib/active_record/transactions.rb:118:in `rollback_active_record_state!'
/vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save'
/app/controllers/opinions_controller.rb:73:in `create'

I think this regression would be better fixed before 1.1.4 or some users will have lots of headache at debugging.
Hope this helps;

Raphaël Valyi

Description

Since rev #7457 "Modify exception construction to memoize frame details in StackTraceElement[] and not construct the Array+String-based backtrace until actually needed", stack traces can be incomplete. Let's take that example taken from a real Rails 2.1 app were I had a raise opinion.inspect statement somewhere inside a file called app/sweepers/opinions_sweeper.rb. So I was actually raising the error myself but had not clue what was going one because of the incorrect log: Here is the stck with JRuby after rev #7457: RuntimeError (#<Opinion id: 254, user_id: 0, topic_id: 85, own_summary: "no", own_text: "", own_url: "", cached_score: 0.0, cached_pool_priority: 0, cached_debt_counter: 0, created_at: "2008-08-22 22:08:23", updated_at: "2008-08-22 22:08:23", cached_level1: nil, cached_level2: nil, cached_tmp_debt_counter: 0, ip_code: 2130706433>): /vendor/rails/activerecord/lib/active_record/transactions.rb:127:in `rollback_active_record_state!' /vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save_with_transactions' /app/controllers/opinions_controller.rb:73:in `create' /vendor/rails/actionpack/lib/action_controller/mime_responds.rb:106:in `call' /vendor/rails/actionpack/lib/action_controller/mime_responds.rb:106:in `respond_to' /app/controllers/opinions_controller.rb:72:in `create' Now, the same error running MRI or a previous JRuby version: RuntimeError (#<Opinion id: 255, user_id: 0, topic_id: 86, own_summary: "my op", own_text: "", own_url: "", cached_score: 0.0, cached_pool_priority: 0, cached_debt_counter: 0, created_at: "2008-08-23 00:23:33", updated_at: "2008-08-23 00:23:33", cached_level1: nil, cached_level2: nil, cached_tmp_debt_counter: 0, ip_code: 2130706433>): /app/sweepers/opinions_sweeper.rb:21:in `expire_cache_for' /app/sweepers/opinions_sweeper.rb:8:in `after_create' /vendor/rails/activerecord/lib/active_record/observer.rb:171:in `send' /vendor/rails/activerecord/lib/active_record/observer.rb:171:in `update' /usr/lib/ruby/1.8/observer.rb:185:in `notify_observers' /usr/lib/ruby/1.8/observer.rb:184:in `each' /usr/lib/ruby/1.8/observer.rb:184:in `notify_observers' /vendor/rails/activerecord/lib/active_record/callbacks.rb:309:in `notify' /vendor/rails/activerecord/lib/active_record/callbacks.rb:302:in `callback' /vendor/rails/activerecord/lib/active_record/callbacks.rb:221:in `create_without_timestamps' /vendor/rails/activerecord/lib/active_record/timestamp.rb:29:in `create' /vendor/rails/activerecord/lib/active_record/base.rb:2464:in `create_or_update_without_callbacks' /vendor/rails/activerecord/lib/active_record/callbacks.rb:207:in `create_or_update' /vendor/rails/activerecord/lib/active_record/base.rb:2192:in `save_without_validation' /vendor/rails/activerecord/lib/active_record/validations.rb:901:in `save_without_dirty' /vendor/rails/activerecord/lib/active_record/dirty.rb:75:in `save_without_transactions' /vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save' /vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:66:in `transaction' /vendor/rails/activerecord/lib/active_record/transactions.rb:79:in `transaction' /vendor/rails/activerecord/lib/active_record/transactions.rb:98:in `transaction' /vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save' /vendor/rails/activerecord/lib/active_record/transactions.rb:118:in `rollback_active_record_state!' /vendor/rails/activerecord/lib/active_record/transactions.rb:106:in `save' /app/controllers/opinions_controller.rb:73:in `create' I think this regression would be better fixed before 1.1.4 or some users will have lots of headache at debugging. Hope this helps; Raphaël Valyi

Show »

Sort Order:

[ Permalink | « Hide ]

Charles Oliver Nutter added a comment - 26/Aug/08 05:25 PM

I made some improvements in r7552 that will hopefully help this. Unfortunately it's really, really hard to find what's different without a reproducible case. Raphael, anything you can do to help confirm this would be greatly appreciated, since nobody else has reported stack trace issues in their apps yet.

[ Permalink | « Hide ]

Raphael Valyi added a comment - 27/Aug/08 06:28 PM

Hi Charlie,

unfortunately, I can tell you that the regression is still there for me, even after your commit. tried with revision #7560 for instance.
I don't have enough time to narrow the bug and I guess it would hardly be a one liner anyway. Still what I'm doing here is just regular Rails cache sweeping as describded in the 'sweepers' section here for instance: http://www.railsenvy.com/2007/2/28/rails-caching-tutorial and I'm just raisong something inside a customized override of the Sweeper#after_create method.

I think what is specific with Rails sweeers is the way the sweeping method is attached to an ActiveRecord event. Indeed, that looks like AOP using an around_filter method under the cover and that might be what makes raise loosing it's complete stack trace.
I tried raising some exception inside a basic around_filter added method added to some controller, but I had the stack printed properly. I get the true AOP logic of the cache sweeping method is more subtile than the basic thing I had time to try.

So if you want to look how things get wired up, then I suggest you have a look to those Rails files (plus tutorial for basic understanding):

ActionController::Caching::Sweeper inside rails/actionpack/action_controller/caching/sweeping.rb
esecially that piece of code attaching the sweeper callback to the controller:
sweepers.each do |sweeper|
ActiveRecord::Base.observers << sweeper if defined?(ActiveRecord) and defined?(ActiveRecord::Base)
sweeper_instance = (sweeper.is_a?(Symbol) ? Object.const_get(sweeper.to_s.classify) : sweeper).instance

Finally keep in mind that the stack was printing properly before commit #7457, so may be you can work out what is behaving differently or may be just roll back the change if the win feels uncertain comparing to that obvious regression since 1.13. May be the bug is also not occurring in many cases, but I can't tell it right now. Looking at raise stack trace remains something exceptionnal so I think that's why nobody else reported the bug yet. But it turns to be very important when you need it.

Anything I can do, like instrumenting my code to help you more?
Best regards,

Raphaël Valyi.

[ Show » ]

Raphael Valyi added a comment - 27/Aug/08 06:28 PM Hi Charlie,

unfortunately, I can tell you that the regression is still there for me, even after your commit. tried with revision #7560 for instance.
I don't have enough time to narrow the bug and I guess it would hardly be a one liner anyway. Still what I'm doing here is just regular Rails cache sweeping as describded in the 'sweepers' section here for instance: http://www.railsenvy.com/2007/2/28/rails-caching-tutorial and I'm just raisong something inside a customized override of the Sweeper#after_create method.

I think what is specific with Rails sweeers is the way the sweeping method is attached to an ActiveRecord event. Indeed, that looks like AOP using an around_filter method under the cover and that might be what makes raise loosing it's complete stack trace. I tried raising some exception inside a basic around_filter added method added to some controller, but I had the stack printed properly. I get the true AOP logic of the cache sweeping method is more subtile than the basic thing I had time to try. So if you want to look how things get wired up, then I suggest you have a look to those Rails files (plus tutorial for basic understanding):

ActionController::Caching::Sweeper inside rails/actionpack/action_controller/caching/sweeping.rb esecially that piece of code attaching the sweeper callback to the controller: sweepers.each do |sweeper| ActiveRecord::Base.observers << sweeper if defined?(ActiveRecord) and defined?(ActiveRecord::Base) sweeper_instance = (sweeper.is_a?(Symbol) ? Object.const_get(sweeper.to_s.classify) : sweeper).instance

if sweeper_instance.is_a?(Sweeper) around_filter(sweeper_instance, :only => configuration[:only]) else after_filter(sweeper_instance, :only => configuration[:only]) end end -then how filters works and especially how around_filter works in rails/actionpack/action_controller/filters.rb see the AroundFilter class Finally keep in mind that the stack was printing properly before commit #7457, so may be you can work out what is behaving differently or may be just roll back the change if the win feels uncertain comparing to that obvious regression since 1.13. May be the bug is also not occurring in many cases, but I can't tell it right now. Looking at raise stack trace remains something exceptionnal so I think that's why nobody else reported the bug yet. But it turns to be very important when you need it. Anything I can do, like instrumenting my code to help you more? Best regards, Raphaël Valyi.

[ Permalink | « Hide ]

Charles Oliver Nutter added a comment - 09/Feb/09 11:03 AM

This is obviously pretty old now...but are you still seeing this? I'd like to get stack traces closer to correct, though largely they're always going to differ somewhat because of optimizations I don't think we want to give up.