Fixing Rails' Action Cable logger

cover photo credit: Niels Heidenreich, https://www.flickr.com/photos/schoschie/282706867
this story was originally published on Medium on Nov 4, 2018, see link

Action Cable has been with us for a couple of years now, and seems to be doing a pretty good job at being a simple, out-of-the-box Rails-driven Web Sockets solution. While it’s not as mature as Rails’ standard REST interface, it actually rather seamlessly, just as it should.

However, when developing Action Cable projects you might have noticed its “interesting” approach towards logging. After making a couple of Web Socket requests to your Action Cable backend, you may see a rather loose and chaotic stream of logs, all fired at different phases of request/response handling and lacking a common structure. The “standard” Rails REST middleware has become a subject of criticism and gems such as Lograge openly define themselves as

“attempting to bring sanity to Rails’ noisy and unusable, unparsable (…) default logging output.”

And, well, Action Cable is also affected.

So let’s have a look. Here are a few logs generated by Action Cable during the opening of Web Sockets connection, subscribing to a channel and calling a Web Socket method:

GET "/ws" [WebSocket] for 127.0.0.1 at 2018-11-03 18:25:00 +0200
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)

...

ApiChannel is streaming from api:c0f1054d-3e2e-47be-bef0-9d66f3f2ac70

...

[ActionCable] Broadcasting to api:41196d5e-cab3-4fa3-bbef-9b5d400caae7: {:params=>{:my_key=>"my_value", :current_status=>"online"}}

That looks pretty wild. There are request data logged here and there, but in other cases we’re left with vague debug-like messages which aren’t really informative. Honestly speaking, it looks rather random. Or does it? Here are some examples from the source code:

# action_cable/connection/subscriptions.rb

logger.error "Received unrecognized command in #{data.inspect}"

# action_cable/channel/base.rb

logger.error "Unable to process #{action_signature(action, data)}"

# action_cable/connection/message_buffer.rb

connection.logger.error "Couldn't handle non-string message: #{message.class}"

Well, it kind of does. Almost feels as if somebody forgot to remove his/her own development-only debug logs. Unfortunately, multiple Action Cable source code files are littered with those arbitrary logger calls. So how do we fix it? First, let's think about how we can silence all unnecessary logs.

Silencing Action Cable logs

Option 1 (bad): Monkey-patch everything.

Taking advantage of capabilities of Ruby, we can reopen Action Cable methods and remove/adjust all redundant logger calls. Of course, this is tedious and may break whenever there is an update to Action Cable's source code but at the same time, it is least intrusive in a sense that we're not touching the default logger implementation.

Option 2: Try to do it systematically.

Instead of reopening every single Action Cable class in which there is a logger call, we can override the Action Cable logger and set it to a "dummy" instance which doesn't produce any output. To achieve this, add this to your config/application.rb:

ActionCable.server.config.logger = Logger.new(nil)

Obviously you may want to keep default logs in e.g. development only; in such case it’s enough to set this empty logger in config/environments/production.rb or other environment configuration files.

Now, this seems like good enough solution to our problem, but bear in mind that it results with virtually all Action Cable logs being disabled. That includes those already present in e.g. custom Connection and Channel classes defined in your app. To get around it, you may want to change all logger calls (which delegate to ActionCable.server.logger) to the standard Rails.logger invocations. In short:

logger :info, "Authenticating connection"

would have to be changed to

Rails.logger.info "Authenticating connection"

Producing sensible logs

Now, how do we produce sensible logs — e.g. generated whenever a single action finishes processing, just as we’d expect it in REST calls.

Option 1: Monkey-patching (again)

Again, monkey-patching is an option, and it should work fine when you just want to have one or two specific logs, e.g. after every subscription and Web Sockets action being called. Just reopen ActionCable::Connection::Subscriptions#execute_command:

module ActionCable
  module Connection
    class Subscriptions
      def execute_command(data)
        case data["command"]
        when "subscribe"
          add data
          Rails.logger.info "Registered subscription: #{data}"
        when "unsubscribe"
          remove data
          Rails.logger.info "Removed subscription: #{data}"
        when "message"
          perform_action data
          Rails.logger.info "Performed action: #{data}"
        else
          Rails.logger.error "Received unrecognized command in #{data.inspect}"
        end
      rescue Exception => e
        Rails.logger.error "Could not execute command from (#{data.inspect}) [#{e.class} - #{e.message}]: #{e.backtrace.first(5).join(" | ")}"
      end
    end
  end
end

(BTW yes, this e.backtrace.first(5).join(" | ") is in the actual Action Cable source code)

This feels pretty good since we’re only reopening a single method handling multiple types of calls: we killed two birds with one stone by adding logs to subscribe, unsubscribe, message actions, and we're able to produce an error log. Now we can do a couple more tweaks: introduce common payload, calculate processing times etc., but again: this would work until we update Rails and there happens to be a change introduced in this very method, or the method could just be removed because of some refactoring. So can we do better?

Option 2: ActiveSupport::Notifications to the rescue

Thankfully, Rails has introduced the ActiveSupport::Notifications API which can be neatly used to define and subscribe to arbitrary events, defined as blocks of code. There are plenty of guides to ActiveSupport::Notifications, but what's most important to us is that in Action Cable source code itself there already are some pre-instrumented parts of code which we can subscribe to:

• ActionCable::Server::Broadcasting includes broadcast.action_cable instrumentation
• ActionCable::Channel::Base includes perform_action.action_cable, transmit.action_cable, transmit_subscription_confirmation.action_cable, transmit_subscription_rejection.action_cable instrumentations

This means we can safely “intercept” any of those messages and produce a log whenever it has finished processing. How do we do that? As an addition to “regular” event subscriptions, Rails also provides a special ActiveSupport::LogSubscriber interface designed to consume notifications and generate logs as the only output. For demonstration purposes, let's subscribe to perform_action.action_cable. Let's define a separate initializer, e.g. my_action_cable_log_subscriber.rb:

class MyActionCableLogSubscriber < ActiveSupport::LogSubscriber
  def perform_action(event)
    info "[Action Cable] #{event.payload[:channel_class]} - #{event.payload[:action]} (Duration: #{event.duration})"
  end
end

MyActionCableLogSubscriber.attach_to :action_cable

As you can see, we had to create a class inheriting from ActiveSupport::LogSubscriber. In it we'd have to define a method named exactly as the instrumentation name, in this example: perform_action. This method accepts a single event argument which is an ActiveSupport::Notifications::event object containing data defined in instrumentation itself and some additional calculated metrics (e.g. duration). Finally, we can generate an info log - the method delegates to the ActiveSupport logger (Rails.logger by default). Feel free to experiment with it, e.g. by creating an error log in case of an exception:

class MyActionCableLogSubscriber < ActiveSupport::LogSubscriber
  def perform_action(event)
    base_log = "#{event.payload[:channel_class]} - #{event.payload[:action]}"

    exception = event.payload[:exception_object]
    if exception
      error "[Action Cable - Failure] #{base_log} (Error: #{exception.message})"
    else
      info "[Action Cable] #{base_log} (Duration: #{event.duration})"
    end
  end
end

MyActionCableLogSubscriber.attach_to :action_cable

This will produce following logs:

[Action Cable] MyChannel - my_method (Duration: 5.57)
...
[Action Cable - Failure] MyChannel - my_method (Error: Invalid)

Similarly, we could add other methods such as broadcast or transmit, but keep in mind that they need to match the instrumentation name. Then, all we need to do is to register our subscriber to action_cable scope by calling attach_to. Pretty simple, eh?

Unfortunately, not everything is instrumented: we’re still lacking instrumentations in open, close, subscribed and unsubscribed actions. Fixing this requires (again) monkey patching or fixing this once and for all in Action Cable source code.

Happy coding with Action Cable!