appsignal-ruby icon indicating copy to clipboard operation
appsignal-ruby copied to clipboard

Rails.error.report is missing information compared to Appsignal.set_error

Open bdewater-thatch opened this issue 11 months ago • 2 comments

Describe the bug

After https://github.com/appsignal/appsignal-ruby/issues/779 and related pull requests we decided to give this new interface a spin - frankly it's a bit nicer interface to use and especially to test (with assert_error_reported).

I basically find/replaced Appsignal.set_error usage with Rails.error.report but I'm noticing a few differences on our staging environment, and I'm not seeing anything in the docs about it so I'm assuming it's a bug.

Here are the links to samples in case it helps Appsignal employees investigate:

To Reproduce

Steps to reproduce the behavior:

  • Using AppSignal for Ruby gem version 3.6.1
  • In my app using Rails 7.1.3.2
  • With this controller code:
      def create
      status = :created
    
      events_params.each do |event_params|
        Appsignal.tag_request(event_id: event_params[:id], event_type: event_params[:type])
        # process event
      rescue => e
        Appsignal.set_error(e)
        status = :internal_server_error
        break
      end
    
      head(status)
    end
    
  • Change Appsignal.set_error(e) to Rails.error.report(e)

Noticeable differences in the web interface:

  • Rails misses method, path and request_method tags for the sample, adds severity and source (the latter to be expected, the former not)
  • Rails is missing the Parameters block below the stack trace 😞
  • Rails is missing the Environment block below the parameters

bdewater-thatch avatar Mar 07 '24 16:03 bdewater-thatch

Hi @bdewater-thatch!

I believe the issue with the missing data is what our docs describe under "Namespace and action for the current transaction" and "Tags for the current transaction".

Long story short: our traces can only contain one error. Since Rails.error.report could be called more than once, or alongside an unhandled error, our listener to Rails.error.report uses send_error to send a new trace with the error, and it attempts to copy the current trace. But some information about the trace is only added after the trace has been processed, and that information will be missing when Rails.error.report is called.

unflxw avatar Mar 08 '24 12:03 unflxw

Thanks @unflxw - that's a subtle change in behaviour from our set_error usage to send_error what the Appsignal error subscriber uses.

Looks like we've been lucky (or missed it) that a trace can only contain a single error since we've been using set_error throughout our app. The docs on set_error vs send_error do not mention this and it feels like it should. Maybe set_error should guard against being called multiple times too?

bdewater-thatch avatar Mar 08 '24 17:03 bdewater-thatch

This is not ideal, but the recommended way to work around this would be to call send_error instead of set_error, and manually add contextual information to the error.

Maybe set_error should guard against being called multiple times too?

Our policy is to never throw errors in the application due to the misuse of AppSignal's helpers -- this is to prevent causing issues in production. But we should at least log something to appsignal.log.

unflxw avatar Mar 11 '24 13:03 unflxw

Our policy is to never throw errors in the application due to the misuse of AppSignal's helpers -- this is to prevent causing issues in production. But we should at least log something to appsignal.log.

Makes sense on both.

This is not ideal, but the recommended way to work around this would be to call send_error instead of set_error, and manually add contextual information to the error.

So I tried this:

class ApplicationController < ActionController::Base
  # set this as the first callback
  before_action :set_appsignal_request_context

  private
  
  # adapted from https://github.com/appsignal/appsignal-ruby/blob/b75109f712363fb1edc8c0ad691346cdd56ae8b9/lib/appsignal/rack/rails_instrumentation.rb#L37-L44
  def set_appsignal_request_context
    transaction = Appsignal::Transaction.current
    transaction.set_action_if_nil("#{self.class}##{action_name}")
    transaction.set_http_or_background_queue_start
    transaction.set_metadata("path", request.path)
    transaction.set_metadata("method", request.request_method)
    transaction.params = request.filtered_parameters
  end
end

but after debugging a Rails.error.report call and going into the Appsignal subscriber, I noticed that path, method or params are not copied over from the current Appsignal transaction here: https://github.com/appsignal/appsignal-ruby/blob/b75109f712363fb1edc8c0ad691346cdd56ae8b9/lib/appsignal/integrations/railtie.rb#L92-L103

nor does there seem a way via that this path to set those three by hand - eg via appsignal context hash - so something is still missing here IMO.

bdewater-thatch avatar Mar 11 '24 20:03 bdewater-thatch

This would add most of the missing stuff, except the environment (headers):

diff --git lib/appsignal/integrations/railtie.rb lib/appsignal/integrations/railtie.rb
index 0bfbc59b..d9f29473 100644
--- lib/appsignal/integrations/railtie.rb
+++ lib/appsignal/integrations/railtie.rb
@@ -60,9 +60,12 @@ module Appsignal
           return unless handled
 
           Appsignal.send_error(error) do |transaction|
-            namespace, action_name, tags, custom_data = context_for(context.dup)
+            namespace, action_name, path, method, params, tags, custom_data = context_for(context.dup)
             transaction.set_namespace(namespace) if namespace
             transaction.set_action(action_name) if action_name
+            transaction.set_metadata("path", path)
+            transaction.set_metadata("method", method)
+            transaction.params = params
             transaction.set_sample_data("custom_data", custom_data) if custom_data
 
             tags[:severity] = severity
@@ -81,9 +84,15 @@ module Appsignal
           # Fetch the namespace and action name based on the Rails execution
           # context.
           controller = context.delete(:controller)
+          path = nil
+          method = nil
+          params = nil
           if controller
             namespace = Appsignal::Transaction::HTTP_REQUEST
             action_name = "#{controller.class.name}##{controller.action_name}"
+            path = controller.request.path
+            method = controller.request.method
+            params = controller.request.filtered_parameters
           end
           # ActiveJob transaction naming relies on the current AppSignal
           # transaction namespace and action name copying done after this.
@@ -115,7 +124,7 @@ module Appsignal
           end
           tags.merge!(context)
 
-          [namespace, action_name, tags, custom_data]
+          [namespace, action_name, path, method, params, tags, custom_data]
         end
       end
     end

bdewater-thatch avatar Mar 12 '24 00:03 bdewater-thatch

Thank you! Yes, that would be an improvement. If you open a pull request for that, we can merge it in as a partial improvement.

That said, I believe that we should have a more general solution for it -- something that covers the issues with set_error and send_error as well. We should either allow for several errors to be reported in the same transaction, and report it both as a performance sample and an error sample, or provide a way to "clone" a transaction.

unflxw avatar Mar 12 '24 11:03 unflxw

@unflxw do you want a separate issue for the general solution stuff you mentioned?

bdewater-thatch avatar Mar 12 '24 16:03 bdewater-thatch

No, don't worry, that'll be a bigger task on our end. (In the AppSignal agent, probably)

unflxw avatar Mar 12 '24 16:03 unflxw

Re-opening this to use as a tracking issue for #1053 and pending work mentioned within it (headers are still missing)

unflxw avatar Mar 14 '24 19:03 unflxw