delayed_job breaks if psych YAML parser is loaded #199

Closed
pda opened this Issue Feb 3, 2011 · 18 comments
@pda
pda commented Feb 3, 2011

Cross-posted: tenderlove/psych#9
Pull request: collectiveidea/delayed_job#200

Loading psych before delayed_job causes the latter to crash.

$ ruby -rdelayed_job -e"puts :hello"
hello

$ ruby -rpsych -rdelayed_job -e"puts :hello"
/Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed/yaml_ext.rb:30:in `remove_method': method `to_yaml' not defined in Class (NameError)
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed/yaml_ext.rb:30:in `<class:Class>'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed/yaml_ext.rb:28:in `<top (required)>'
    from <internal:lib/rubygems/custom_require>:29:in `require'
    from <internal:lib/rubygems/custom_require>:29:in `require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed_job.rb:6:in `<top (required)>'
    from <internal:lib/rubygems/custom_require>:33:in `require'
    from <internal:lib/rubygems/custom_require>:33:in `rescue in require'
    from <internal:lib/rubygems/custom_require>:29:in `require'

This is because of delayed_job-2.1.3/lib/delayed/yaml_ext.rb (abridged):

require 'yaml'

class Module
  def to_yaml( opts = {} )
    YAML::quick_emit( nil, opts ) { |out|
      out.scalar(taguri, self.name, :plain)
    }
  end
end

class Class
  remove_method :to_yaml # use Module's to_yaml
end
@joshfng

Would you happen to have a fix for this?

@pda
pda commented Feb 3, 2011

Yep.. I've submitted pull request #200 (updated) #201.

In the mean time, you can change your Gemfile to:

gem "delayed_job", :git => "git://github.com/pda/delayed_job.git"

Here's the differences between it and the latest stable v2.1.3:
pda/delayed_job@v2.1.3...master

Cheers,
Paul

@joshfng

Hmm I had already tried that. When I do that, delayed_job starts but when any of my methods try to insert a job the app dies with a "stack level too deep" error.

Here is an example job that causes the crash:

Mailer.delay.invitation(current_user.username, @invitation, signup_url(@invitation.token))

@pda
pda commented Feb 3, 2011

I don't have any problem inserting delayed_jobs, but looks like I can't run them later...

ruby-1.9.2-p136 :001 > User.first.delay.inspect
 => #<Delayed::Backend::ActiveRecord::Job id: 15, priority: 0, attempts: 0, handler: "--- !ruby/struct:Delayed::PerformableMethod\nobject:...", last_error: nil, run_at: "2011-02-03 02:43:34", locked_at: nil, failed_at: nil, locked_by: nil, created_at: "2011-02-03 02:43:34", updated_at: "2011-02-03 02:43:34"> 

$ tail -n1 log/delayed_job.log 
2011-02-03T13:44:01+1100: [Worker(delayed_job host:paulbookpro.lan pid:42427)] User#inspect failed with NoMethodError: undefined method `keys' for nil:NilClass - 0 failed attempts

I'm happy to have rails server running at least :)

All the delayed_job tests are passing:

$ echo "create database delayed_job" | mysql
$ rake
(in /home/paul/pda/delayed_job)
...........................................................................................

Finished in 2.53 seconds
91 examples, 0 failures

That's me stuck for the moment..

@benhoskings

Haven't had a chance to fully test this yet, but: benhoskings/delayed_job@c3a28f9

@pda
pda commented Feb 3, 2011

I'm afraid that doesn't seem to do the job:

# With psych enabled, benhoskings/delayed_job.git

$ rails c
Loading development environment (Rails 3.0.3)

ruby-1.9.2-p136 :001 > User.first.delay.inspect
 => #<Delayed::Backend::ActiveRecord::Job id: 20, priority: 0, attempts: 0, handler: "--- !ruby/struct:Delayed::PerformableMethod\nobject:...", last_error: nil, run_at: "2011-02-03 07:53:54", locked_at: nil, failed_at: nil, locked_by: nil, created_at: "2011-02-03 07:53:54", updated_at: "2011-02-03 07:53:54"> 

ruby-1.9.2-p136 :002 > Delayed::Worker.new.work_off
NoMethodError: undefined method `keys' for nil:NilClass
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/whiny_nil.rb:48:in `method_missing'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activerecord-3.0.3/lib/active_record/base.rb:1512:in `attribute_names'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activerecord-3.0.3/lib/active_record/base.rb:1569:in `attributes'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activerecord-3.0.3/lib/active_record/attribute_methods.rb:57:in `attribute_method?'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activemodel-3.0.3/lib/active_model/attribute_methods.rb:394:in `block in match_attribute_method?'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activemodel-3.0.3/lib/active_model/attribute_methods.rb:393:in `each'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activemodel-3.0.3/lib/active_model/attribute_methods.rb:393:in `match_attribute_method?'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activemodel-3.0.3/lib/active_model/attribute_methods.rb:378:in `respond_to?'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activerecord-3.0.3/lib/active_record/attribute_methods.rb:52:in `respond_to?'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/performable_method.rb:28:in `respond_to?'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/backend/base.rb:118:in `max_attempts'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:162:in `max_attempts'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:136:in `reschedule'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:170:in `handle_failed_job'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:129:in `rescue in run'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:119:in `run'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:177:in `reserve_and_run_one_job'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:104:in `block in work_off'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:103:in `times'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/bundler/gems/delayed_job-c3a28f971456/lib/delayed/worker.rb:103:in `work_off'
    from (irb):2
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/railties-3.0.3/lib/rails/commands/console.rb:44:in `start'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/railties-3.0.3/lib/rails/commands/console.rb:8:in `start'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/railties-3.0.3/lib/rails/commands.rb:23:in `<top (required)>'
    from script/rails:6:in `require'
    from script/rails:6:in `<main>'ruby-1.9.2-p136 :003 > 

Compared to:

# With psych disabled, benhoskings/delayed_job.git

$ rails c
Loading development environment (Rails 3.0.3)

ruby-1.9.2-p136 :001 > User.first.delay.inspect
 => #<Delayed::Backend::ActiveRecord::Job id: 19, priority: 0, attempts: 0, handler: "--- !ruby/struct:Delayed::PerformableMethod \nobject...", last_error: nil, run_at: "2011-02-03 07:52:53", locked_at: nil, failed_at: nil, locked_by: nil, created_at: "2011-02-03 07:52:53", updated_at: "2011-02-03 07:52:53"> 

ruby-1.9.2-p136 :002 > Delayed::Worker.new.work_off
 => [2, 0] 

And here's the same test against collectiveidea/delayed_job.git

# With psych enabled, collectiveidea/delayed_job.git

$ rails c
/Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed/yaml_ext.rb:30:in `remove_method': method `to_yaml' not defined in Class (NameError)
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed/yaml_ext.rb:30:in `<class:Class>'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed/yaml_ext.rb:28:in `<top (required)>'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/dependencies.rb:239:in `require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/dependencies.rb:239:in `block in require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/dependencies.rb:225:in `block in load_dependency'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/dependencies.rb:596:in `new_constants_in'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/dependencies.rb:225:in `load_dependency'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/activesupport-3.0.3/lib/active_support/dependencies.rb:239:in `require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/delayed_job-2.1.3/lib/delayed_job.rb:6:in `<top (required)>'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler/runtime.rb:68:in `require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler/runtime.rb:68:in `block (2 levels) in require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler/runtime.rb:66:in `each'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler/runtime.rb:66:in `block in require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler/runtime.rb:55:in `each'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler/runtime.rb:55:in `require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/bundler-1.0.10/lib/bundler.rb:120:in `require'
    from /Users/paul/learnable/learnaby/config/application.rb:7:in `<top (required)>'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/railties-3.0.3/lib/rails/commands.rb:21:in `require'
    from /Users/paul/.rvm/gems/ruby-1.9.2-p136/gems/railties-3.0.3/lib/rails/commands.rb:21:in `<top (required)>'
    from script/rails:6:in `require'
    from script/rails:6:in `<main>'

 # With psych disabled, collectiveidea/delayed_job.git

$ rails c
Loading development environment (Rails 3.0.3)

ruby-1.9.2-p136 :001 > User.first.delay.inspect
 => #<Delayed::Backend::ActiveRecord::Job id: 18, priority: 0, attempts: 0, handler: "--- !ruby/struct:Delayed::PerformableMethod \nobject...", last_error: nil, run_at: "2011-02-03 07:50:57", locked_at: nil, failed_at: nil, locked_by: nil, created_at: "2011-02-03 07:50:57", updated_at: "2011-02-03 07:50:57"> 

ruby-1.9.2-p136 :002 > Delayed::Worker.new.work_off
 => [10, 0] 

For testing, I disabled psych by putting an if false around the entire contents of ruby-1.9.2-p136/lib/ruby/1.9.1/psych.rb - not sure if there's a better way.

@pda
pda commented Feb 3, 2011

Below is a diff of the stored YAML between psych disabled and psych enabled.

Key parts:

-object: !ruby/ActiveRecord:User 
+object: !ruby/object:User

and

-    customer_id: 
-    photo_id: 
+    customer_id: !!null 
+    photo_id: !!null 

The full diff:

--- psych_disabled.yml  2011-02-03 19:09:55.000000000 +1100
+++ psych_enabled.rb    2011-02-03 19:09:32.000000000 +1100
@@ -1,36 +1,36 @@
 --- !ruby/struct:Delayed::PerformableMethod 
-object: !ruby/ActiveRecord:User 
+object: !ruby/object:User
   attributes: 
     id: 12345
-    customer_id: 
-    photo_id: 
+    customer_id: !!null 
+    photo_id: !!null 
     email: blarg@example.org
     username: blarg
-    full_name: ""
+    full_name: ''
     encrypted_password: $2a$10$yTXe...W6tu
     salt: ea...87
     auth_hash: e5...56b
     active: 1
     activation_key: 3a1...a8b
-    last_visit: 2010-10-21 17:53:45 Z
-    last_ip: 
+    last_visit: 2010-10-21 17:53:45.000000000Z
+    last_ip: !!null 
     this_ip: 127.0.0.1
     signup_notifications: 0
     course_notifications: 0
     newsletter: 1
-    date_of_birth: 
-    timezone: ""
-    country: 
+    date_of_birth: !!null 
+    timezone: ''
+    country: !!null 
     enabled: 1
-    confirmation_token: 
-    confirmed_at: 2011-02-01 17:50:40 Z
-    confirmation_sent_at: 
+    confirmation_token: !!null 
+    confirmed_at: 2011-02-01 17:50:40.000000000Z
+    confirmation_sent_at: !!null 
     sign_in_count: 0
-    current_sign_in_at: 
-    last_sign_in_at: 
-    current_sign_in_ip: 
-    last_sign_in_ip: 
-    created_at: 
-    updated_at: 
+    current_sign_in_at: !!null 
+    last_sign_in_at: !!null 
+    current_sign_in_ip: !!null 
+    last_sign_in_ip: !!null 
+    created_at: !!null 
+    updated_at: !!null 
 method_name: :inspect
 args: []
@pda
pda commented Feb 3, 2011

Building on benhoskings patch, I believe this is fixed in pda/delayed_job@0f61afd by forcing YAML::ENGINE.yamler = "syck".

Of course, delayed_job should be fixed more thoroughly to work with either syck or psych, as the latter will soon be the default.

@pda
pda commented Feb 3, 2011

Submitted pull request collectiveidea/delayed_job#201

@gaffneyc
Collective Idea member

194 was marked as a duplicate of this bug.

Gist: Bundler 1.0.10 loads Psych by default so stick to Bundler 1.0.9 and Rubygems < 1.5 until we get a fix in (or use Pda's patch).

@raykin

+1

syck YAML parser broken my app when I serialize a column

@myobie

What's the status on this? I'm having weird issues with 1.9.2 and I think this might be the root cause.

@bryckbost
Collective Idea member

@myobie This shouldn't be an issue if you're on DJ 3.

@iainbeeston

I can reproduce this on DJ 3 if I use syck (ie. through YAML::ENGINE.yamler), but not with psych - @myobie are you sure you're using psych?

@myobie

I was, yes. Removing it does seem to get me to a working state.

@mhuggins

I'm having this issue on DJ3 with SYCK. How do I fix this?

@iainbeeston

To get DJ working for me (on ruby 1.9.2-p290 and rails 3.1) I had to manually set the yamler to psych in boot.rb ("require 'psych'; YAML::ENGINE.yamler = 'psych'").

@corporealfunk

I am also running into an issue with rails 3.2.10, ruby-1.9.2-p290, delayed_job 3.0.5 that I believe is caused by the same psych/syck issue, though I can't trace it's root cause.

However, my symptom is that I get a "stack level too deep error" when I delay a Mailer object method call. Interestingly, the error is not reproduced on the rails console, only when in the context of the running application (nginx+passenger) from a controller.

the work-around suggested by iainbeeston works for me.

@albus522 albus522 closed this Sep 24, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment