roar-rails icon indicating copy to clipboard operation
roar-rails copied to clipboard

Published 20 hours ago • verified publisher icon apotonick

Strange intermittent error /w multipart posts

Open acrispino opened this issue 11 years ago • 19 comments

ruby 1.9.3-p429 rails 3.2.13 representable 1.5.3 roar 0.11.18 roar-rails 0.1.0

I'm experiencing a strange intermittent error involving multipart posts. It happens rarely, but once it starts to happen, it keeps happening until the app server is restarted.

My question is, why is Roar::Representer::JSON::InstanceMethods::to_hash being called? It doesn't seem like roar should be involved here, in the processing of an options hash.

Additionally, considering that Rack::Multipart::Parser always calls Tempfile.new with no options, it seems very strange that the error only manifests some of the time.

Stack trace:

NoMethodError: undefined method `id' for nil:NilClass
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/binding.rb:77:in `block in get'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/binding.rb:93:in `represented_exec_for'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/binding.rb:76:in `get'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/binding.rb:36:in `block in compile_fragment'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/binding.rb:93:in `represented_exec_for'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/binding.rb:35:in `compile_fragment'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable.rb:95:in `compile_fragment'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/roar-0.11.18/lib/roar/representer/json/hal.rb:41:in `compile_fragment'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable.rb:62:in `serialize_property'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/feature/readable_writeable.rb:11:in `serialize_property'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable.rb:55:in `block in create_representation_with'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable.rb:54:in `each'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable.rb:54:in `create_representation_with'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/representable-1.5.3/lib/representable/hash.rb:33:in `to_hash'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/roar-0.11.18/lib/roar/representer/json.rb:21:in `to_hash'
  /usr/local/lib/ruby/1.9.1/tmpdir.rb:117:in `try_convert'
  /usr/local/lib/ruby/1.9.1/tmpdir.rb:117:in `create'
  /usr/local/lib/ruby/1.9.1/tempfile.rb:134:in `initialize'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/multipart/parser.rb:104:in `new'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/multipart/parser.rb:104:in `get_current_head_and_filename_and_content_type_and_name_and_body'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/multipart/parser.rb:19:in `block in parse'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/multipart/parser.rb:17:in `loop'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/multipart/parser.rb:17:in `parse'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/multipart.rb:25:in `parse_multipart'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/request.rb:336:in `parse_multipart'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/request.rb:201:in `POST'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/methodoverride.rb:26:in `method_override'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/methodoverride.rb:14:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/runtime.rb:17:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/lock.rb:15:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/engine.rb:479:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/application.rb:223:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/railtie/configurable.rb:30:in `method_missing'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/lint.rb:48:in `_call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/lint.rb:36:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/showexceptions.rb:24:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/commonlogger.rb:33:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/chunked.rb:43:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/content_length.rb:14:in `call'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:552:in `process_client'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:632:in `worker_loop'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:500:in `spawn_missing_workers'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:142:in `start'
  /mnt/app/shared/bundle/ruby/1.9.1/gems/unicorn-4.6.2/bin/unicorn:126:in `<top (required)>'
  /mnt/app/shared/bundle/ruby/1.9.1/bin/unicorn:23:in `load'
  /mnt/app/shared/bundle/ruby/1.9.1/bin/unicorn:23:in `<main>'

acrispino avatar Jun 20 '13 20:06 acrispino

I guess Tmpdir calls #to_hash and since your object is "polluted" from being extended with the representer it calls the "wrong" #to_hash? Try if that error occurs when using a decorator instead of a representer module.

apotonick avatar Jun 21 '13 11:06 apotonick

The error seems to be occurring too early for my application code to get involved. The request and exception are logged by unicorn, but are not present in the rails log. I also added a logging statement in my controller and it isn't reached when the error occurs.

I also forgot to add, I don't believe this is specific to unicorn. I have also observed this error with rainbows! and puma.

acrispino avatar Jun 21 '13 16:06 acrispino

Look here: http://www.ruby-doc.org/core-1.9.3/Hash.html#method-c-try_convert It really calls #to_hash which is then falsley provided by the already mixed-in representer. There must be a stale instance lurking around somewhere in your stack... Can you patch the Tmpdir thing and see what it tries to convert, please?

apotonick avatar Jun 22 '13 08:06 apotonick

It's converting a nil.

rack-1.4.5/lib/rack/multipart/parser.rb:104

body = Tempfile.new("RackMultipart")

ruby-1.9.3-p429/lib/tempfile.rb:129

def initialize(basename, *rest)
  @data = []
  @clean_proc = Remover.new(@data)
  ObjectSpace.define_finalizer(self, @clean_proc)

  create(basename, *rest) do |tmpname, n, opts|

ruby-1.9.3-p429/lib/tmdir.rb:116

def create(basename, *rest)
  if opts = Hash.try_convert(rest[-1])

to confirm, I modified roar-0.11.18/lib/roar/representer/json.rb:19

    def to_hash(*args)
      if self.nil?
        puts "OxDEADBEEF: " + ::JSON.dump(args)
        return nil
      end
      before_serialize(*args)
      super
    end

And saw this in my logs during some uploads:

2013-06-26_13:58:20.73490 OxDEADBEEF: []
2013-06-26_13:58:21.29914 OxDEADBEEF: []
2013-06-26_13:58:21.46694 OxDEADBEEF: []
2013-06-26_13:58:22.19964 OxDEADBEEF: []

The modification seems to work as a band-aid solution

acrispino avatar Jun 26 '13 17:06 acrispino

You know what? I reckon that nil is mistakenly extended somewhere in your app, this is "cached" across some requests and then roar's #to_hash is called where it shouldn't. Haha, that is ridiculous!

I will investigate on that, that shouldn't happen. But let me say one thing: if it was your fault you owe me 3 beers at least!

apotonick avatar Jun 27 '13 00:06 apotonick

Ok that is exactly the case - somewhere your singleton instance nil is extended with a representer. If you could find out where that would greatly help. Also, extending singletons must be prevented by roar-rails.

apotonick avatar Jun 27 '13 00:06 apotonick

It probably is my fault :( I will have to check all the controllers. oh dear.

acrispino avatar Jun 27 '13 16:06 acrispino

I'm not sure if you have to buy the drinks. The thing is: should roar really extend a singleton object like nil? On the one hand, I say, no exceptions, no magic. On the other hand, I find it a bit dangerous, so maybe roar-rails could check for nil|true|false when using a extend representer and bail out. What do you think?

apotonick avatar Jun 28 '13 00:06 apotonick

I found the erroneous controller. I'll take responsibility for this one.

I understand the concern about magic. But, as you saw, it was a really confusing error and seems worth preventing.

My long term plan is to modify my representers to be decorators, which should eliminate entirely the possibility of this occurring again. Additionally, I now check whether or not nil responds to to_hash after every request so I have a better chance of finding future errors.

acrispino avatar Jul 08 '13 22:07 acrispino

Agreed, we should add a check to roar-rails since this is an ugly hard-to-spot thing. Oh cool, so you buy the beers? Great!

apotonick avatar Jul 09 '13 02:07 apotonick

FWIW, this issue just bit us in the rear. As a hack, I am overriding nil.extend to stop this from happening.

Not sure it's necessarily an roar-rails issue, but it's a doozy.

ruprict avatar Mar 11 '14 22:03 ruprict

Is the problem that it's trying to represent (render) a nil object, @ruprict ?

apotonick avatar Mar 12 '14 02:03 apotonick

Well, I am spitting out a message from my #extend, and I see:

[Server:server-one] ESC[0mESC[0m09:59:24,597 INFO  [stdout] (http-/172.31.0.107:8080-3) **** Stop trying to extend nil, jerk Mail::RFC2822::Address0ESC[0m
[Server:server-one] ESC[0mESC[0m09:59:24,608 INFO  [stdout] (http-/172.31.0.107:8080-3) **** Stop trying to extend nil, jerk Mail::RFC2822::Address0ESC[0m
[Server:server-one] ESC[0mESC[0m09:59:24,613 INFO  [stdout] (http-/172.31.0.107:8080-3) **** Stop trying to extend nil, jerk Mail::RFC2822::Address0ESC[0m
[Server:server-one] ESC[0mESC[0m09:59:24,632 INFO  [stdout] (http-/172.31.0.107:8080-3) **** Stop trying to extend nil, jerk Mail::RFC2822::Address0ESC[0m]

I am not sure where this is coming from (I haven't investigated)

Then, there's:

[Server:server-one] ESC[0mESC[0m11:16:14,572 INFO  [stdout] (http-/172.31.0.107:8080-3) **** Stop trying to extend nil, jerk PlayerRepresenterESC[0m

Which is ours (PlayerRepresenter) . I haven't been able to reproduce it outside of production yet. but, we were seeing errors like Undefined method id for NilClass inside PlayerRepresenter.

So, yeah, I think something was nil, and we (or a gem) called nil.extend(PlayerReprsenter) so that the next render of a Player called to_hash on nil and BOOM.

Again, the fact that I am calling nil.extend is not a roar-rails issue, but I thought I'd add this in case others are seeing such oddities.

ruprict avatar Mar 12 '14 10:03 ruprict

You're passing a nil object to respond_with which shouldn't run the representer code. What's the standard behaviour in Rails?

apotonick avatar Mar 12 '14 21:03 apotonick

Actually, in our case, we may explicitly be calling player.extend(PlayerRepresenter) when player is nil (but we don't think it is)

In other words, I think, in our case, this is indicative of something we are effing up.

I don't think Rails is getting involved here.

Nick Sutterer wrote:

You're passing a |nil| object to |respond_with| which shouldn't run the representer code. What's the standard behaviour in Rails?

— Reply to this email directly or view it on GitHub https://github.com/apotonick/roar-rails/issues/46#issuecomment-37466089.

ruprict avatar Mar 12 '14 22:03 ruprict

Ok, if you pass a nil object into respond_to and roar-rails tries to extend it, I am wrong. I will check that.

If you extend a nil object yourself, you're wrong. Please check that. :grin:

apotonick avatar Mar 12 '14 23:03 apotonick

Hello there, I see this is quite an old ticket, but I just stumpled upon the very same issue. nil is passed into respond_with and we kinda rely on getting a response body containing only the string "null" – however, roar extends it and then just fails to serialize any of the configured properties, of course. I tried explicitly disabling roar in the case of the object being nil, by passing represented_formats: [], but that doesn't seem to work. (I tried at several other points in the past, and it never worked, by the way, even though it's documented like that. Regards

Aaaah, it was my own fault, too. :)

besief avatar Jun 09 '15 14:06 besief

Thanks! I might open Roar-rails to be "community supported" as I am not interested in supporting "the Rails Way" anymore because it's wrong and misleading people.

After the Roar integration with Trailblazer is finished it might be more obvious how wrong things are handled in the "Rails Way" and how much more intuitive it is to structure your code into operations that know which representer to use for which model.

Sorry if that doesn't help you! :stuck_out_tongue_winking_eye:

apotonick avatar Jun 09 '15 22:06 apotonick

We just ran into this, and I figured I'd share the super dirty way we caught where exactly this was happening.

If you overwrite the extend method for NilClass in config/initializers/nil.rb to something like:

def extend(*args)
  puts "Hey, don't wanna do this"
  sleep 20
end

it should be pretty obvious when/where this happens.

Hope this helps anyone else who runs into this!

fatcatt316 avatar Jun 02 '16 18:06 fatcatt316