Dd-trace-rb: Ruby logs truncated in APM traces

[TildeWill]

This past week I went to respond to an alert from APM and found that the log had been truncated and didn't show where in my app code the problem was coming from, the Tags tab view only showed the library lines before being truncated.

ddtrace (0.26.0)

ActionView::Template::Error: incompatible character encodings: ASCII-8BIT and UTF-8

/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/string/output_safety.rb:187:in `concat'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/string/output_safety.rb:187:in `concat'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/buffers.rb:14:in `<<'
/app/app/views/layouts/application.html.erb:15:in `_app_views_layouts_application_html_erb__2364249821955660676_47175401689460'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/template.rb:159:in `block in render'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/notifications.rb:170:in `instrument'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/template.rb:354:in `instrument_render_template'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/template.rb:157:in `render'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/renderer/template_renderer.rb:66:in `render_with_layout'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/renderer/template_renderer.rb:52:in `render_template'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/contrib/rails/core_extensions.rb:80:in `render_template_with_datadog'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/renderer/template_renderer.rb:16:in `render'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/contrib/rails/core_extensions.rb:42:in `block (2 levels) in render_with_datadog'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/contrib/rails/core_extensions.rb:93:in `with_datadog_span'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/contrib/rails/core_extensions.rb:42:in `block in render_with_datadog'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/tracer.rb:303:in `trace'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/contrib/rails/core_extensions.rb:38:in `render_with_datadog'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/renderer/renderer.rb:44:in `render_template'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/renderer/renderer.rb:25:in `render'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/rendering.rb:103:in `_render_template'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/streaming.rb:219:in `_render_template'
/usr/local/bundle/gems/actionview-5.2.3/lib/action_view/rendering.rb:84:in `render_to_body'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:52:in `render_to_body'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/renderers.rb:142:in `render_to_body'
/usr/local/bundle/gems/actionpack-5.2.3/lib/abstract_controller/rendering.rb:25:in `render'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:36:in `render'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:46:in `block (2 levels) in render'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/benchmark.rb:14:in `block in ms'
/usr/local/lib/ruby/2.6.0/benchmark.rb:308:in `realtime'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/benchmark.rb:14:in `ms'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:46:in `block in render'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:87:in `cleanup_view_runtime'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:45:in `render'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/implicit_render.rb:35:in `default_render'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `block in send_action'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `tap'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/local/bundle/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:194:in `process_action'
/usr/local/bundle/gems/ddtrace-0.26.0/lib/ddtrace/contrib/rails/action_controller_patch.rb:49:in `process_action'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/local/bundle/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/app/app/controllers/concerns/internationalization.rb:28:in `block in with_locale'
/usr/local/bundle/gems/i18n-1.6.0/lib/i18n.rb:297:in `with_locale'
/app/app/controllers/concerns/internationalization.rb:28:in `with_locale'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/local/bundle/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/local/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr...

Is there a way to raise the line-limit so more of the stack trace is shown? Something else I should look at?

Thanks!

[TildeWill]

A coworker pointed out that the stacktrace cuts out right at 5,000 characters, which matches the MaxMetaValLen constant in the datadog-agent: https://github.com/DataDog/datadog-agent/blob/master/pkg/trace/agent/truncator.go#L28

[delner]

Thanks for the report @TildeWill! I think you found the likely source; the agent tag limits. Definitely can see why you need the full stack trace, not just the first 5K characters, so this is a good catch. The Ruby tracer should send the stack trace in full, but I'll have to follow up with the agent team about this limit. I'll try to keep you posted here.

[ZimbiX]

I see this issue has been closed - is it fixed now?

[TildeWill]

Not fixed as far as I know. But hadn't seen movement on it since October and it's no longer a pressing issue for us. Feel free to reopen.

[delner]

My recommendation would be to open a support ticket through the Datadog website, as the issue seems to manifest in the agent. They should be able to route the issue to the team that can address it.