Custom EventFormatters are wonky/dangerous

[ryansch]

The way custom formatters work now is a bit wonky.

Example Setup:

Pathname.glob('./lib/appsignal_formatters/*.rb').each do |file|
  require file
end
Appsignal::EventFormatter.initialize_formatters # won't work without reinitializing formatters

The real issue I ran into was with my Dalli formatter.

module AppsignalFormatters
  class DalliFormatter < Appsignal::EventFormatter
    register 'cache_read.active_support'
    register 'cache_read_multi.active_support'
    register 'cache_fetch_multi.active_support'
    register 'cache_write.active_support'
    register 'cache_delete.active_support'
    register 'cache_increment.active_support'
    register 'cache_decrement.active_support'
    register 'cache_clear.active_support'

    def format(payload)
      # multi actions pass an array of keys
      key = payload[:key]
      if key.is_a? Array
        key = key.join(',')
      end

      [
        key.to_s
      ]
    end
  end
end

The original version of this code had the following format method:

def format(payload)
  [
    payload[:key]
  ]
end

That managed to get through dev/test just fine but when I pushed it into production it took out two main sections of our website. I failed to notice that Dalli passes an Array of key names for the read_multi and fetch_multi events. This caused the appsignal gem (extension?) to raise an error because it was expecting a string instead of an array.

I think the fix here should be catching any errors that could happen in a formatter and logging them instead. Additionally, an 'external register' method or clear documentation on how to add custom formatters would probably help the next person to integrate.

[jeffkreeftmeijer]

Hey @ryansch,

Thanks for reporting this, and sorry for causing issues in your app. We’d rather not turn the exceptions into warnings here, because that’d hide errors in the code, making it more difficult to debug. Of course, we try to make this as robust as possible, but adding type checks here could increase overhead (and raising an error when a type check fails would bring us back where we started).

We’ll add some more thorough documentation for implementing formatters, so it’s clearer what type of response we’re expecting from the #format method.

Thanks again for letting us know about this!

[ryansch]

@jeffkreeftmeijer Could we make it configurable? I'm accepting arbitrary data from various gems and if any of them change that data in an incompatible way in a future update and I don't notice then I'm going to be right back here. We have centralized logging and I can alert on log events so it's not a visibility issue for me.

[thijsc]

You could catch the exception in the formatter yourself and log that. We have a testing matrix for most of these (see https://github.com/appsignal/appsignal-ruby/tree/master/gemfiles). Our normal approach is to make the formatters very resilient and test them with everything we integrate with.

Would you be open to turning your code into a pull on this repo? We can then make it part of the whole testing setup. I'm wondering: Why do you need specific Dali integration? Does the standard Rails binding not provide enough information?

[ryansch]

The problem is that the formatter didn't raise an exception. It unexpectedly returned an array instead of a string. That caused an exception to be raised inside of finish_event (https://github.com/appsignal/appsignal-ruby/blob/master/lib/appsignal/hooks/active_support_notifications.rb#L40) which I can't rescue from inside the formatter.

I'd be fine with adding PRs for my Dalli and Excon formatters. I added them after looking at what we were getting with new relic and wanting access to that information inside of appsignal.

[ryansch]

Excon requires a little hackery to get their AS::Notification names correct (https://github.com/excon/excon#instrumentation).

class ExconInstrumentor
  # Excon names its notifications backwards from the rest of the
  # ActiveSupport::Notifications ecosystem.  They even admit it
  # in the README.  We reverse the name here for sanity.
  def self.instrument(name, datum, &block)
    namespace, *event = name.split(".")
    rails_name = [event, namespace].flatten.join(".")
    ActiveSupport::Notifications.instrument(rails_name, datum, &block)
  end
end

Excon.defaults[:instrumentor] = ExconInstrumentor

I'm conflicted over whether or not that code should be enabled by default. If we do include it, is it an integration or a hook? I was a bit confused as to the difference while looking through the code in this gem.

[thijsc]

That would be a hook. The hook system can determine which dependencies are present and add some custom behaviour if they are.

This is indeed a little complicated behaviour, but sometimes there's no way around it with formatters.