From 367832cde8d3bb364e98910e60e3215b7b7bc249 Mon Sep 17 00:00:00 2001 From: "Christian Mauduit (DataDog)" Date: Thu, 23 Mar 2017 18:44:03 +0100 Subject: [PATCH 1/2] [contrib:rails] reporting controller exceptions as errors in stats --- lib/ddtrace/contrib/rails/action_controller.rb | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/lib/ddtrace/contrib/rails/action_controller.rb b/lib/ddtrace/contrib/rails/action_controller.rb index c7cecaeaa3f..7d14daef6ab 100644 --- a/lib/ddtrace/contrib/rails/action_controller.rb +++ b/lib/ddtrace/contrib/rails/action_controller.rb @@ -51,15 +51,17 @@ def self.process_action(_name, start, finish, _id, payload) if payload[:exception].nil? # [christian] in some cases :status is not defined, # rather than firing an error, simply acknowledge we don't know it. - span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, payload.fetch(:status, '?').to_s) + status = payload.fetch(:status, '?').to_s + span.status = 1 if status.starts_with?('50') + span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, status) else error = payload[:exception] - # TODO[manu]: it's right to have a 500? there are cases in Rails that let - # user to recover the error after this point? span.status = 1 span.set_tag(Datadog::Ext::Errors::TYPE, error[0]) span.set_tag(Datadog::Ext::Errors::MSG, error[1]) - span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, '500') + # [manu,christian]: it's right to have a 500? there are cases in Rails that let + # user to recover the error after this point? + span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, payload.fetch(:status, '500').to_s) end ensure From 60726ceb0481eca737d4a609bbf47bb308c64b4a Mon Sep 17 00:00:00 2001 From: "Christian Mauduit (DataDog)" Date: Fri, 24 Mar 2017 11:00:12 +0100 Subject: [PATCH 2/2] [contrib:rails] enhanced controller error handling --- .../contrib/rails/action_controller.rb | 6 ++- lib/ddtrace/span.rb | 2 +- test/contrib/rails/apps/controllers.rb | 10 +++++ test/contrib/rails/controller_test.rb | 37 +++++++++++++++++++ test/contrib/rails/database_test.rb | 2 +- 5 files changed, 54 insertions(+), 3 deletions(-) diff --git a/lib/ddtrace/contrib/rails/action_controller.rb b/lib/ddtrace/contrib/rails/action_controller.rb index 7d14daef6ab..9d9197d29cb 100644 --- a/lib/ddtrace/contrib/rails/action_controller.rb +++ b/lib/ddtrace/contrib/rails/action_controller.rb @@ -52,13 +52,17 @@ def self.process_action(_name, start, finish, _id, payload) # [christian] in some cases :status is not defined, # rather than firing an error, simply acknowledge we don't know it. status = payload.fetch(:status, '?').to_s - span.status = 1 if status.starts_with?('50') + if status.starts_with?('5') + span.status = 1 + span.set_tag(Datadog::Ext::Errors::STACK, caller().join('\n')) + end span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, status) else error = payload[:exception] span.status = 1 span.set_tag(Datadog::Ext::Errors::TYPE, error[0]) span.set_tag(Datadog::Ext::Errors::MSG, error[1]) + span.set_tag(Datadog::Ext::Errors::STACK, caller().join('\n')) # [manu,christian]: it's right to have a 500? there are cases in Rails that let # user to recover the error after this point? span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, payload.fetch(:status, '500').to_s) diff --git a/lib/ddtrace/span.rb b/lib/ddtrace/span.rb index 6e13191c9c2..62c8f37e344 100644 --- a/lib/ddtrace/span.rb +++ b/lib/ddtrace/span.rb @@ -86,7 +86,7 @@ def set_error(e) @status = 1 @meta[Datadog::Ext::Errors::MSG] = e.message if e.respond_to?(:message) && e.message @meta[Datadog::Ext::Errors::TYPE] = e.class.to_s - @meta[Datadog::Ext::Errors::STACK] = e.backtrace.join("\n") if e.respond_to?(:backtrace) && e.backtrace + @meta[Datadog::Ext::Errors::STACK] = e.backtrace.join('\n') if e.respond_to?(:backtrace) && e.backtrace end # Mark the span finished at the current time and submit it. diff --git a/test/contrib/rails/apps/controllers.rb b/test/contrib/rails/apps/controllers.rb index 9fcad4fc5f4..8ed9f256170 100644 --- a/test/contrib/rails/apps/controllers.rb +++ b/test/contrib/rails/apps/controllers.rb @@ -12,6 +12,7 @@ class TracingController < ActionController::Base 'views/tracing/partial.html.erb' => 'Hello from <%= render "views/tracing/body.html.erb" %>', 'views/tracing/full.html.erb' => '<% Article.all.each do |article| %><% end %>', 'views/tracing/error.html.erb' => '<%= 1/0 %>', + 'views/tracing/soft_error.html.erb' => 'nothing', 'views/tracing/error_partial.html.erb' => 'Hello from <%= render "views/tracing/inner_error.html.erb" %>', 'views/tracing/_body.html.erb' => '_body.html.erb partial', 'views/tracing/_inner_error.html.erb' => '<%= 1/0 %>' @@ -30,6 +31,14 @@ def error 1 / 0 end + def soft_error + if Rails::VERSION::MAJOR.to_i >= 5 + head 520 + else + render nothing: true, status: 520 + end + end + def error_template render 'views/tracing/error.html.erb' end @@ -49,6 +58,7 @@ def full get '/partial' => 'tracing#partial' get '/full' => 'tracing#full' get '/error' => 'tracing#error' + get '/soft_error' => 'tracing#soft_error' get '/error_template' => 'tracing#error_template' get '/error_partial' => 'tracing#error_partial' end diff --git a/test/contrib/rails/controller_test.rb b/test/contrib/rails/controller_test.rb index 5cd31a15ce5..8bb630cc58d 100644 --- a/test/contrib/rails/controller_test.rb +++ b/test/contrib/rails/controller_test.rb @@ -95,4 +95,41 @@ class TracingControllerTest < ActionController::TestCase assert_response :success assert_nil(Thread.current[:datadog_span]) end + + test 'error should be trapped and reported as such' do + err = false + begin + get :error + rescue + err = true + end + assert_equal(true, err, 'should have raised an error') + spans = @tracer.writer.spans() + assert_equal(1, spans.length) + span = spans[0] + assert_equal('rails.request', span.name) + assert_equal(1, span.status, 'span should be flagged as an error') + assert_equal('ZeroDivisionError', span.get_tag('error.type'), 'type should contain the class name of the error') + assert_equal('divided by 0', span.get_tag('error.msg'), 'msg should state we tried to divided by 0') + assert_match(/ddtrace/, span.get_tag('error.stack'), 'stack should contain the call stack when error was raised') + assert_equal('500', span.get_tag('http.status_code'), 'status should be 500 error by default') + end + + test 'http error code should be trapped and reported as such, even with no exception' do + get :soft_error + + spans = @tracer.writer.spans() + if Rails::VERSION::MAJOR.to_i >= 5 + assert_equal(1, spans.length) + else + assert_equal(2, spans.length, 'legacy code (rails <= 4) uses render with a status, so there is an extra render span') + end + span = spans[spans.length - 1] + assert_equal('rails.request', span.name) + assert_equal(1, span.status, 'span should be flagged as an error') + assert_nil(span.get_tag('error.type'), 'type should be undefined') + assert_nil(span.get_tag('error.msg'), 'msg should be empty') + assert_match(/ddtrace/, span.get_tag('error.stack'), 'stack should contain the call stack when error was raised') + assert_equal('520', span.get_tag('http.status_code'), 'status should be 520 Web server is returning an unknown error') + end end diff --git a/test/contrib/rails/database_test.rb b/test/contrib/rails/database_test.rb index def4cea34b6..b83e45b5be4 100644 --- a/test/contrib/rails/database_test.rb +++ b/test/contrib/rails/database_test.rb @@ -24,7 +24,7 @@ class DatabaseTracingTest < ActiveSupport::TestCase assert_equal(span.span_type, 'sql') assert_equal(span.service, adapter_name) assert_equal(span.get_tag('rails.db.vendor'), adapter_name) - assert_equal(span.get_tag('rails.db.cached'), nil) + assert_nil(span.get_tag('rails.db.cached')) assert_includes(span.resource, 'SELECT COUNT(*) FROM') # ensure that the sql.query tag is not set assert_nil(span.get_tag('sql.query'))