Fixing Rails' Action Cable logger
Tags: ruby, rails, actioncable, webdev
Published: 2020-04-21 18:19:19

_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](https://medium.com/@xlts/fixing-rails-action-cable-logger-7fd0597251cc?source=friends_link&sk=1fb9160c6565f036c53316a883596367)_

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:

```ruby
# 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`:

```ruby
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:

```ruby
logger :info, "Authenticating connection"
```

would have to be changed to

```ruby
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`:

```ruby
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`](https://api.rubyonrails.org/classes/ActiveSupport/Notifications.html) 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`](https://api.rubyonrails.org/classes/ActiveSupport/LogSubscriber.html) 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`:

```ruby
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.logge`r by default). Feel free to experiment with it, e.g. by creating an `error` log in case of an exception:

```ruby
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!