Dd-trace-rb: NoMethodError: undefined method `status' for #<Array:0x000000116d9758>

[frsantos]

After updating to 0.12.0, I get this exception anytime a user logs in with a wrong password.

/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rails/core_extensions.rb:224:in `process_action'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/abstract_controller/base.rb:124:in `process'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_controller/metal.rb:189:in `dispatch'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_controller/metal.rb:242:in `block in action'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/devise-4.4.1/lib/devise/failure_app.rb:23:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/devise-4.4.1/lib/devise/delegator.rb:7:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/warden-1.2.7/lib/warden/manager.rb:143:in `call_failure_app'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/warden-1.2.7/lib/warden/manager.rb:129:in `process_unauthenticated'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/warden-1.2.7/lib/warden/manager.rb:44:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/etag.rb:25:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/conditional_get.rb:38:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/head.rb:12:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:232:in `context'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:226:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/activerecord-5.1.4/lib/active_record/migration.rb:556:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:97:in `run_callbacks'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/executor.rb:12:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rollbar-2.15.5/lib/rollbar/middleware/rails/rollbar.rb:24:in `block in call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rollbar-2.15.5/lib/rollbar.rb:145:in `scoped'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rollbar-2.15.5/lib/rollbar/middleware/rails/rollbar.rb:22:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rollbar-2.15.5/lib/rollbar/middleware/rails/show_exceptions.rb:22:in `call_with_rollbar'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/web-console-3.5.1/lib/web_console/middleware.rb:135:in `call_app'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/web-console-3.5.1/lib/web_console/middleware.rb:28:in `block in call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/web-console-3.5.1/lib/web_console/middleware.rb:18:in `catch'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/web-console-3.5.1/lib/web_console/middleware.rb:18:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rails/middlewares.rb:16:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-dev-mark-0.7.7/lib/rack/dev-mark/middleware.rb:19:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/rack/logger.rb:36:in `call_app'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/rack/logger.rb:26:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/request_store-1.4.0/lib/request_store/middleware.rb:19:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/method_override.rb:22:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/runtime.rb:22:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/executor.rb:12:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/actionpack-5.1.4/lib/action_dispatch/middleware/static.rb:125:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/sendfile.rb:111:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/middlewares.rb:53:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/engine.rb:522:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/ddtrace-0.12.0/lib/ddtrace/contrib/rack/patcher.rb:63:in `call'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606:in `process_client'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701:in `worker_loop'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142:in `start'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/unicorn-rails-2.2.1/lib/unicorn_rails.rb:33:in `run'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/rack-2.0.4/lib/rack/server.rb:297:in `start'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:44:in `start'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:135:in `block in perform'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:130:in `tap'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:130:in `perform'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/thor-0.20.0/lib/thor/command.rb:27:in `run'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/thor-0.20.0/lib/thor/invocation.rb:126:in `invoke_command'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/thor-0.20.0/lib/thor.rb:387:in `dispatch'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/command/base.rb:63:in `perform'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/command.rb:44:in `invoke'
/home/test/.rvm/gems/ruby-2.3.3@prj/gems/railties-5.1.4/lib/rails/commands.rb:16:in `<top (required)>'
/home/test/Proyectos/prj/prj/bin/rails:4:in `require'
/home/test/Proyectos/prj/prj/bin/rails:4:in `<top (required)>'
-e:1:in `load'
-e:1:in `<main>'

The error is in the line

payload[:status] = response.status

When I inspect the response object, I get this array (not a Response object):
[200, {"X-Frame-Options"=>"SAMEORIGIN", "X-XSS-Protection"=>"1; mode=block", "X-Content-Type-Options"=>"nosniff", "Content-Type"=>"text/html; charset=utf-8"}, #<ActionDispatch::Response::RackBody:0x0000000f1b2c40>]

[delner]

@frsantos Thanks for the report. Does your application implement any middleware that might be changing the object passed down the chain? That Array looks like a Rack middleware response; such a thing would be unusual to appear as the response within an ActionController.

It's possible this is related to this commit where we now prepend a tracing module (instead of rewriting the method on the class, to avoid conflicts.)

Could you narrow down the differences between a successful request and a request that produces this error? Especially as it affects what response appears as? I'd take a closer look at what process_unauthenticated in Warden is doing.

[frsantos]

@delner No, we don't implement any middleware .

The only difference is the Devise::FailureApp (that inherits from ActionController::Metal) that Devise uses internally. Maybe that ActionController::Metal is the one changing the response.

[delner]

We're prepending the patch to ActionController::Metal. I'm willing to bet that it has something to do with Devise implementing that directly, without implementing the module that converts the Rack response to the equivalent Rails response object.

I'll dive deeper into this.

[delner]

Okay, so this might be a "bug" with Devise.

They're doing an override in their FailureApp to change the content of ActionController::Metal#response from an ActionDispatch::Response object into an Array, which breaks tracing because it expects an ActionDispatch::Response object.

From what I can tell, does this because FailureApp is meant to wrap around Warden. However, I'm not sure if they're aware that the response of ActionController::Metal#dispatch when called for Warden doesn't actually return a ActionDispatch::Response object, but an Array. Thus this might be a mistake.

I think maybe the simplest way around this is to add some kind of type-checking in the tracing patch, so that it handles this okay. I think this really should be changed in Devise, though.

[delner]

@frsantos Pull request here... want to check it out? Let me know if it works for you? https://github.com/DataDog/dd-trace-rb/pull/420

[frsantos]

@delner Yes, that fixes it, thanks. :1st_place_medal:

[delner]

@frsantos Glad to hear! We'll roll this into our next bugfix release.

[fruwe]

Fixed it for me as well

[delner]

This has been merged into master, and will roll when 0.12.1 is released. I'll close this issue when that happens.

[delner]

Release 0.12.1 should roll next week, and this fix along with it. Going to close this now. Thanks for your contribution!