Undefined method `span_id' for nil:NilClass with long requests #445

jvalanen · 2018-06-06T07:14:35Z

In our application we have very complicated and long listings with tons of html elements. It can take even 300+ seconds for the view to render.

Shorter listings render fine but for those longer ones we receive status=500 error='ActionView::Template::Error: undefined method 'span_id' for nil:NilClass':

This error happens with ddtrace versions >= 0.12.0, downgrading to 0.11.4 helped for us.

Response:

method=GET path=/foo/6302256 format=html controller=FooController action=show status=500 error='ActionView::Template::Error: undefined method `span_id' for nil:NilClass' duration=165571.01 view=0.00 db=8886.01

View template looks about like this: (entries array may include 2000+ items...)

- entries.each do |entry|
  %tr
    %td
      .row
        = render partial: 'foo', locals: {foo: bar}
    %td
      .row
        = render partial: 'foo/items', locals: {foo: bar, items: bar.items(:one)}
    %td
      .row
        = render partial: 'foo/items', locals: {foo: bar, items: bar.items(:two)}

And inside items partial again:

items.each do |item|
  ...
end

Full trace:

ddtrace (0.12.0) lib/ddtrace/contrib/rails/core_extensions.rb:133:in `current_span_id'
ddtrace (0.12.0) lib/ddtrace/contrib/rails/core_extensions.rb:106:in `ensure in render_with_datadog'
ddtrace (0.12.0) lib/ddtrace/contrib/rails/core_extensions.rb:109:in `render_with_datadog'
actionview (4.2.1) lib/action_view/renderer/renderer.rb:47:in `render_partial'
actionview (4.2.1) lib/action_view/renderer/renderer.rb:21:in `render'
actionview (4.2.1) lib/action_view/helpers/rendering_helper.rb:32:in `render'
haml (4.0.7) lib/haml/helpers/action_view_mods.rb:10:in `block in render_with_haml'
haml (4.0.7) lib/haml/helpers.rb:89:in `non_haml'
haml (4.0.7) lib/haml/helpers/action_view_mods.rb:10:in `render_with_haml'
app/views/foo/show.html.haml:22:in `_app_views_foo_show_html_haml___1150221759246532801_70168924389520'
actionview (4.2.1) lib/action_view/template.rb:145:in `block in render'
activesupport (4.2.1) lib/active_support/notifications.rb:166:in `instrument'
actionview (4.2.1) lib/action_view/template.rb:333:in `instrument'
actionview (4.2.1) lib/action_view/template.rb:143:in `render'
actionview (4.2.1) lib/action_view/renderer/template_renderer.rb:54:in `block (2 levels) in render_template'
actionview (4.2.1) lib/action_view/renderer/abstract_renderer.rb:39:in `block in instrument'
activesupport (4.2.1) lib/active_support/notifications.rb:166:in `instrument'
actionview (4.2.1) lib/action_view/renderer/abstract_renderer.rb:39:in `instrument'
actionview (4.2.1) lib/action_view/renderer/template_renderer.rb:53:in `block in render_template'
actionview (4.2.1) lib/action_view/renderer/template_renderer.rb:61:in `render_with_layout'
actionview (4.2.1) lib/action_view/renderer/template_renderer.rb:52:in `render_template'
ddtrace (0.12.0) lib/ddtrace/contrib/rails/core_extensions.rb:70:in `render_template_with_datadog'
actionview (4.2.1) lib/action_view/renderer/template_renderer.rb:14:in `render'
ddtrace (0.12.0) lib/ddtrace/contrib/rails/core_extensions.rb:38:in `render_with_datadog'
actionview (4.2.1) lib/action_view/renderer/renderer.rb:42:in `render_template'
actionview (4.2.1) lib/action_view/renderer/renderer.rb:23:in `render'
actionview (4.2.1) lib/action_view/rendering.rb:100:in `_render_template'
actionpack (4.2.1) lib/action_controller/metal/streaming.rb:217:in `_render_template'
actionview (4.2.1) lib/action_view/rendering.rb:83:in `render_to_body'
actionpack (4.2.1) lib/action_controller/metal/rendering.rb:32:in `render_to_body'
actionpack (4.2.1) lib/action_controller/metal/renderers.rb:37:in `render_to_body'
actionpack (4.2.1) lib/abstract_controller/rendering.rb:25:in `render'
actionpack (4.2.1) lib/action_controller/metal/rendering.rb:16:in `render'
actionpack (4.2.1) lib/action_controller/metal/instrumentation.rb:44:in `block (2 levels) in render'
activesupport (4.2.1) lib/active_support/core_ext/benchmark.rb:12:in `block in ms'
/usr/local/lib/ruby/2.2.0/benchmark.rb:303:in `realtime'
activesupport (4.2.1) lib/active_support/core_ext/benchmark.rb:12:in `ms'
actionpack (4.2.1) lib/action_controller/metal/instrumentation.rb:44:in `block in render'
actionpack (4.2.1) lib/action_controller/metal/instrumentation.rb:87:in `cleanup_view_runtime'
activerecord (4.2.1) lib/active_record/railties/controller_runtime.rb:25:in `cleanup_view_runtime'
actionpack (4.2.1) lib/action_controller/metal/instrumentation.rb:43:in `render'
wicked_pdf (1.1.0) lib/wicked_pdf/pdf_helper.rb:42:in `render_with_wicked_pdf'
actionpack (4.2.1) lib/action_controller/metal/implicit_render.rb:10:in `default_render'
actionpack (4.2.1) lib/action_controller/metal/implicit_render.rb:5:in `send_action'
actionpack (4.2.1) lib/abstract_controller/base.rb:198:in `process_action'
ddtrace (0.12.0) lib/ddtrace/contrib/rails/core_extensions.rb:223:in `process_action'
actionpack (4.2.1) lib/action_controller/metal/rendering.rb:10:in `process_action'
actionpack (4.2.1) lib/abstract_controller/callbacks.rb:20:in `block in process_action'
activesupport (4.2.1) lib/active_support/callbacks.rb:117:in `call'
activesupport (4.2.1) lib/active_support/callbacks.rb:117:in `call'
activesupport (4.2.1) lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
activesupport (4.2.1) lib/active_support/callbacks.rb:505:in `call'
activesupport (4.2.1) lib/active_support/callbacks.rb:505:in `call'
activesupport (4.2.1) lib/active_support/callbacks.rb:92:in `_run_callbacks'
activesupport (4.2.1) lib/active_support/callbacks.rb:776:in `_run_process_action_callbacks'
activesupport (4.2.1) lib/active_support/callbacks.rb:81:in `run_callbacks'
actionpack (4.2.1) lib/abstract_controller/callbacks.rb:19:in `process_action'
actionpack (4.2.1) lib/action_controller/metal/rescue.rb:29:in `process_action'
actionpack (4.2.1) lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
activesupport (4.2.1) lib/active_support/notifications.rb:164:in `block in instrument'
activesupport (4.2.1) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
activesupport (4.2.1) lib/active_support/notifications.rb:164:in `instrument'
actionpack (4.2.1) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
actionpack (4.2.1) lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
activerecord (4.2.1) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
actionpack (4.2.1) lib/abstract_controller/base.rb:137:in `process'
actionview (4.2.1) lib/action_view/rendering.rb:30:in `process'
actionpack (4.2.1) lib/action_controller/metal.rb:196:in `dispatch'
actionpack (4.2.1) lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
actionpack (4.2.1) lib/action_controller/metal.rb:237:in `block in action'
actionpack (4.2.1) lib/action_dispatch/routing/route_set.rb:74:in `call'
actionpack (4.2.1) lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
actionpack (4.2.1) lib/action_dispatch/routing/route_set.rb:43:in `serve'
actionpack (4.2.1) lib/action_dispatch/journey/router.rb:43:in `block in serve'
actionpack (4.2.1) lib/action_dispatch/journey/router.rb:30:in `each'
actionpack (4.2.1) lib/action_dispatch/journey/router.rb:30:in `serve'
actionpack (4.2.1) lib/action_dispatch/routing/route_set.rb:819:in `call'
warden (1.2.6) lib/warden/manager.rb:35:in `block in call'
warden (1.2.6) lib/warden/manager.rb:34:in `catch'
warden (1.2.6) lib/warden/manager.rb:34:in `call'
rack (1.6.4) lib/rack/etag.rb:24:in `call'
rack (1.6.4) lib/rack/conditionalget.rb:25:in `call'
rack (1.6.4) lib/rack/head.rb:13:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/params_parser.rb:27:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/flash.rb:260:in `call'
rack (1.6.4) lib/rack/session/abstract/id.rb:225:in `context'
rack (1.6.4) lib/rack/session/abstract/id.rb:220:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/cookies.rb:560:in `call'
activerecord (4.2.1) lib/active_record/query_cache.rb:36:in `call'
activerecord (4.2.1) lib/active_record/connection_adapters/abstract/connection_pool.rb:649:in `call'
activerecord (4.2.1) lib/active_record/migration.rb:378:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
activesupport (4.2.1) lib/active_support/callbacks.rb:88:in `call'
activesupport (4.2.1) lib/active_support/callbacks.rb:88:in `_run_callbacks'
activesupport (4.2.1) lib/active_support/callbacks.rb:776:in `_run_call_callbacks'
activesupport (4.2.1) lib/active_support/callbacks.rb:81:in `run_callbacks'
actionpack (4.2.1) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/reloader.rb:73:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
ddtrace (0.12.0) lib/ddtrace/contrib/rails/middlewares.rb:16:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
lograge (0.9.0) lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
railties (4.2.1) lib/rails/rack/logger.rb:20:in `block in call'
activesupport (4.2.1) lib/active_support/tagged_logging.rb:68:in `block in tagged'
activesupport (4.2.1) lib/active_support/tagged_logging.rb:26:in `tagged'
activesupport (4.2.1) lib/active_support/tagged_logging.rb:68:in `tagged'
railties (4.2.1) lib/rails/rack/logger.rb:20:in `call'
request_store (1.4.1) lib/request_store/middleware.rb:19:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/request_id.rb:21:in `call'
rack (1.6.4) lib/rack/methodoverride.rb:22:in `call'
rack (1.6.4) lib/rack/runtime.rb:18:in `call'
activesupport (4.2.1) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
rack (1.6.4) lib/rack/lock.rb:17:in `call'
actionpack (4.2.1) lib/action_dispatch/middleware/static.rb:113:in `call'
rack (1.6.4) lib/rack/sendfile.rb:113:in `call'
ddtrace (0.12.0) lib/ddtrace/contrib/rack/middlewares.rb:53:in `call'
railties (4.2.1) lib/rails/engine.rb:518:in `call'
railties (4.2.1) lib/rails/application.rb:164:in `call'
rack (1.6.4) lib/rack/content_length.rb:15:in `call'
puma (3.4.0) lib/puma/configuration.rb:224:in `call'
puma (3.4.0) lib/puma/server.rb:569:in `handle_request'
puma (3.4.0) lib/puma/server.rb:406:in `process_client'
puma (3.4.0) lib/puma/server.rb:271:in `block in run'
puma (3.4.0) lib/puma/thread_pool.rb:114:in `call'
puma (3.4.0) lib/puma/thread_pool.rb:114:in `block in spawn_thread'

The text was updated successfully, but these errors were encountered:

delner · 2018-06-06T15:43:38Z

@jvalanen Thanks for the report!

If I'm interpreting the issue correctly, it looks like the trace isn't being started, thus when it tries to get the span_id of the current trace, it turns up as a NoMethodError.

In the past, this sort of thing has happened when another gem conflicts with our Rails injection. I see that you have wicked_pdf injected, which appears to be overwriting the render method which likely conflicts with Datadog's controller patch. If you were to remove this gem, albeit temporarily, would the issue persist?

This might not be an explanation for the issue you're seeing, so any other configuration, Gemfile.lock files, logs, or counter examples would be helpful here.

Does this issue affect all of your controllers/routes? If not, is the length the only factor? (Is there some number which definitively separates the successes from the failures?) Are there other routes that generate shorter renders that suffer the same issue?

Can you tell me more about the routes affected, and what are they doing? Are they making many DB calls per render? (Multiplied by however many partials there are?)

Unless you're hitting some kind of hard limit on the number of spans in your trace (which I don't think is happening), I suspect this might have more to do with Rails being improperly patched than an issue of scale. But I'd be happy to dig in and find out if you can provide me with a little more info!

delner · 2018-06-06T17:09:24Z

Also possibly related #302 which was released in 0.11.0.

delner · 2018-06-06T18:25:54Z

I setup a Rails 5.1.4 application using ddtrace 0.13.0.beta1 with wicked_pdf 1.1.0 and a view with the following:

index.html.erb:

<!DOCTYPE html>
<html>
  <head>
    <title>Test PDF</title>
  </head>
  <body>
    <table>
      <% 100000.times do |i| %>
        <tr>
          <td>
            <%= render partial: 'line', locals: { index: i } %>
          </td>
        </tr>
      <% end %>
    </table>
  </body>
</html>

_line.html.erb:

Line <%= index %>

This had no problems at 1000, or 10,000 lines. It started to struggle at 100,000 lines, where it produced the following:

Rendered pdf/_line.html.erb (0.0ms)
... (repeats ~100,000 times) ...
D, [2018-06-06T14:14:43.568451 #3967] DEBUG -- ddtrace: [ddtrace] (dd-trace-rb/lib/ddtrace/context.rb:74:in `block in add_span') context full, ignoring span rails.render_partial
  Rendered pdf/_line.html.erb (0.0ms)
D, [2018-06-06T14:14:43.569453 #3967] DEBUG -- ddtrace: [ddtrace] (dd-trace-rb/lib/ddtrace/context.rb:74:in `block in add_span') context full, ignoring span rails.render_partial
  Rendered pdf/_line.html.erb (0.0ms)
D, [2018-06-06T14:14:43.570330 #3967] DEBUG -- ddtrace: [ddtrace] (dd-trace-rb/lib/ddtrace/context.rb:74:in `block in add_span') context full, ignoring span rails.render_partial
  Rendered pdf/_line.html.erb (0.0ms)
  Rendered pdf/index.html.erb (84125.4ms)
Completed 200 OK in 84128ms (Views: 84126.8ms | ActiveRecord: 0.0ms)

So if you have a trace that's producing over 100K spans, it's conceivable you might run into issues. That said, this still didn't produce an exception like your issue details, so it's not clear how that happened.

delner · 2018-06-06T19:10:06Z

You also mentioned that things were better on 0.11.4 vs 0.12.0. Looking at the diff between the tags, there were no changes to our render partial tracing, so this might be a side effect of some other kind of change.

Would it be possible to activate debug mode, and share any debug messages you might receive? You can do so by adding the following to your configuration:

Datadog.configure do |c|
  c.tracer debug: true
end

Any logs you could share would help greatly!

delner · 2018-06-07T20:13:13Z

@jvalanen I opened #447 which should help address this bug. Would you be able to try it to confirm if it works for you?

jvalanen · 2018-06-08T10:58:44Z

Hey @delner, thanks for the super quick response and inspecting this issue!

I didn't have time to dive into this yesterday but as my colleague @onnimonni had already tested, it seems to fix our that specific issue! Good job!

I didn't follow completely how you traced this down but it makes sense that we hit some hard limit in rendering and it crashed because of that.

I suppose this was enough to fix this particular issue. Or would it be beneficial for you if I could deliver some specific logs about this issue?

Thanks so much!

delner · 2018-06-08T20:57:13Z

@jvalanen Glad to hear it works for you!

Logs would be helpful, if you can provide them. Somehow it seemed something was off with your trace context, but I wasn't able to explain why despite looking quite deeply into it. That PR instead simply sidestepped the issue, by refactoring the code which avoids the direct consequences of that.

This will probably roll with our 0.12.1 release currently scheduled for June 12th. Thanks for your report! Will close this issue when the fix is merged.

jvalanen changed the title ~~"Undefined method `span_id' for nil:NilClass" with long requests~~ Undefined method `span_id' for nil:NilClass with long requests Jun 6, 2018

delner self-assigned this Jun 6, 2018

delner added bug Involves a bug integrations Involves tracing integrations community Was opened by a community member labels Jun 6, 2018

delner mentioned this issue Jun 7, 2018

Fix ActionView tracing contexts when span limit is reached #447

Merged

delner closed this as completed in #447 Jun 11, 2018

delner added this to the 0.12.1 milestone Aug 14, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Undefined method `span_id' for nil:NilClass with long requests #445

Undefined method `span_id' for nil:NilClass with long requests #445

jvalanen commented Jun 6, 2018

delner commented Jun 6, 2018

delner commented Jun 6, 2018

delner commented Jun 6, 2018

delner commented Jun 6, 2018 •

edited

delner commented Jun 7, 2018

jvalanen commented Jun 8, 2018

delner commented Jun 8, 2018

Undefined method `span_id' for nil:NilClass with long requests #445

Undefined method `span_id' for nil:NilClass with long requests #445

Comments

jvalanen commented Jun 6, 2018

delner commented Jun 6, 2018

delner commented Jun 6, 2018

delner commented Jun 6, 2018

delner commented Jun 6, 2018 • edited

delner commented Jun 7, 2018

jvalanen commented Jun 8, 2018

delner commented Jun 8, 2018

delner commented Jun 6, 2018 •

edited