Building a Custom Logger with Active Support Tagged Logging
Tags: rails, ruby, activesupport, taggedlogger
Published: 2017-09-27 15:38:57

---
title: Building a Custom Logger with Active Support Tagged Logging
published: true
description: Use Active Support Tagged Logging to build a flexible, reusable custom Rails logger
tags: Rails, Ruby, Active Support, Tagged Logger
---
*This post was [originally published](http://www.thegreatcodeadventure.com/building-a-custom-logger-in-rails/) in my blog, [The Great Code Adventure](http://www.thegreatcodeadventure.com/)*. 

The `ActiveSupport::Logger` class is the go-to logging tool for Rails––the default Rails logger represents an instance of this class. Active Support provides some additional flexible logging classes that we can use to customize logging functionality in our Rails app. 

The default logger allows us to set logging levels, for example `WARN`, or `INFO`, or `ERROR`, and log simple statements tagged with that level. 

For example, 

```
logger.info "uploading file #{file_name} to S3..."
```

will log:

```
[INFO] uploading get_schwifty.jpg to S3...
```

to the default, environment-based log file: `<development/staging/test/production>.log`

But what if we need a clean, easy-to-use way to log more complex statements?

For example, let's say you maintain the Rails monolith for a popular e-commerce platform. One responsibility of your application is to pay a seller for any items purchased from a user through your site. For every purchase that occurs, you will distribute payment to the vendor. 

This is an important and complicated code flow––we need to collect the funds for the appropriate product and enact a bank transaction. We definitely want to log the progress of this code flow with as much detail as possible, and we don't want these log statements to get lost in the mix of the overall production logs. I don't want to see a statement about an error with a bank transaction sandwiched between statements about users logging in, for example. 

We wouldn't want something to go wrong mid-way through paying Rick for another sale of one of his trendy Morty Dazzlers, and not be able to identify the issue to quickly resolve it.

![](https://thepracticaldev.s3.amazonaws.com/i/nkgi31f3vwvmfp4h9vgv.png)
 <span style="font-size:12px">source: https://masterofallscience.com (do you guys know about this btw?? some amazing hero made a Rick and Morty gif/meme generator. Strongly recommend.)</span>

## Project Requirements

We have two requirements:

1. Vendor payment log statements should log to their own file, `log/vendor_payment.log`
2. Each log statement that documents this code flow should have the same heading including:
  *  The ID of the vendor being paid and the product for which we are paying them.
  * The date and time.
  * The log level.


```ruby
[INFO 2017-09-15 12:14:1222] < vendor_id: 77801, product_id: 6701, transaction_id: 15110 >
[INFO 2017-09-15 12:14:1222] initiating bank transfer...
```
Additionally, we want our logger to be easy to use. I _don't_ want to have to write two log statements every time we need to log something:

```ruby
my_logger.info "< vendor_id: #{transaction.vendor_id}, product_id: #{transaction.product_id}, transaction_id: #{transaction.id} >"
my_logger.info "initiating bank transfer...
```
I am way too lazy for that nonsense. 

Instead, we should be able to call our customer logger like the default Rails logger, i.e. with one call to the various log-level methods `#info`, `#error`, `#warn`, `#debug`. 

We'll code our custom logger such that we can pass in a second argument of the transaction object, and automatically generate the log statement header each time:

```ruby
my_logger.info "initiating bank transfer...", transaction

=> 
[INFO 2017-09-15 12:14:1222] < vendor_id: 77801, product_id: 6701, transaction_id: 15110 >
[INFO 2017-09-15 12:14:1222] initiating bank transfer...
```
We'll build our custom logger with the help of `ActiveSupport::TaggedLogging` to gain this functionality. 

### What is `ActiveSupport::TaggedLogging`?

[`ActiveSupport::TaggedLogging`](http://api.rubyonrails.org/classes/ActiveSupport/TaggedLogging.html) is used to wrap any standard logger instance to add "tags" to a log statement. A "tag" in this case usually describes a subdomain, and is used by the default `Rails.logger` to allow you to tag log statements with subdomains, request ids, etc. in your multi-user, multi-instance production applications.

What does it mean to "wrap" a standard logger instance? We can invoke an `ActiveSupport::TaggedLogging` instance's `#tagged` method with an argument of the "tag" we want to apply, and a block containing the call to the standard logger's appropriate severity-level method (`#info`, `#error` etc.). 

```ruby
logger = ActiveSupport::TaggedLogging.new(Logger.new("my_log_file.log")

logger.tagged("IP: #{request.ip}") { logger.info "something important is happening" }

=> [INFO][IP: 97.14.98.11] "something important is happening"
``` 

The `TaggedLogging` instance adds the argument we passed to `#tagged` to the message header, and then writes the log statement we passed as an argument to `logger.info`. 

It's important to note that `ActiveSupport::TaggedLogging` implements the [`#tagged`](http://api.rubyonrails.org/classes/ActiveSupport/TaggedLogging.html#method-i-tagged) method itself, while it delegates the `#info`, `#error`, `#warn`, and `#debug` methods to it's `logger` attribute––the log instance we passed in when we called `#new`. 

We'll leverage the `#tagged` method to add our own personal message header stamp to each and every log statement.

### Defining the `VendorPaymentLogger`

To gain access to the `#tagged` method, we'll inherit our custom logger from `ActiveSupport::TaggedLogging`. 

`TaggedLogging` instances expect to be initialized with an argument of an instance of `Logger`. 

```ruby
VendorPaymentLogger.new(Logger.new("log/vendor_payment.log")
```
Notice that we are telling our standard logger instance to write log statements to our custom log file by passing in the name of the file as an argument to `Logger.new`.

#### Defining and Setting the Custom Formatter

Recall that we want our logger class to write log statements not only with our custom "tag", but also with a properly formatted date and time. 

Active Support loggers use the `#formatter` attribute to format the output of log statements. The `#formatter` attribute needs to be set equal to a value that responds to `#call`. 

The formatter is called on by the instance on which we call the severity-level methods (`#info`, `#warn`, etc.). It will be called with the severity level, timestamp, progname (an attribute we won't deal with here) and message. 

We'll build our own custom formatter and save it as a Proc that expects these parameters. 

`TaggedLogging` instances delegate the statement-level methods to the associated standard logger instance. So, we'll define our `#initialize` method to set the `#formatter` attribute of the associated logger instance to our own custom formatter Proc.

```ruby
#lib/vendor_payment_logger.rb

class VendorPaymentLogger < ActiveSupport::TaggedLogging
  def initialize(logger)
    super(logger)
    logger.formatter = formatter
  end

  def formatter
    Proc.new{|severity, time, progname, msg|
      formatted_severity = sprintf("%-5s",severity.to_s)
      formatted_time = time.strftime("%Y-%m-%d %H:%M:%S")
      "[#{formatted_severity} #{formatted_time} #{$$}]\n #{msg}\n"
    }
  end
end
```
At this point, our log statements will look something like this:

```ruby
logger = ActiveSupport::TaggedLogging.new(Logger.new("log/vendor_payment.log")

logger.info "doing a thing now."
=> [INFO 2017-09-15 12:14:2345] doing a thing now
```
#### Overriding the `#tagged` Method

We want each and every log statement written by our `VendorPaymentLogger` to have the following statement before the individual message:

```ruby
<vendor_id: 1234, product_id: 5678, transaction_id: 101112>
```

We _could_ write something like this every time we use our logger:

```ruby
logger = ActiveSupport::TaggedLogging.new(Logger.new("log/vendor_payment.log")

logger.tagged("< vendor_id: #{transaction.vendor_id}, product_id: #{transaction.product_id}, transaction_id: #{transaction.id} >") { (logger.info "doing a thing now." }

=> [INFO 2017-09-15 12:14:2345] <vendor_id: 1234, product_id: 5678, transaction_id: 101112>
=> [INFO 2017-09-15 12:14:2345] doing a thing now
```
I don't know about you but I think that is super awful. I am not interested in having to write that out every time I use this logger. It would be so much nicer if we could use our logger like this:

```ruby

logger.info("doing a thing now", transaction)

=> [INFO 2017-09-15 12:14:2345] <vendor_id: 1234, product_id: 5678, transaction_id: 101112>
=> [INFO 2017-09-15 12:14:2345] doing a thing now
```
Much cleaner. 

In order to get this functionality, we'll have to overwrite the definition of the severity-level methods, and the definition of the `#tagged` method. 

```ruby
 #lib/vendor_payment_logger.rb

class VendorPaymentLogger < ActiveSupport::TaggedLogging
  ...
  def info(msg, transaction)
    tagged(transaction) { super(msg) }
  end

  def warn(msg, transaction)
    tagged(transaction) { super(msg) }
  end

  def debug(msg, transaction)
    tagged(transaction) { super(msg) }
  end

  def error(msg, transaction)
    tagged(transaction) { super(msg) }
  end

  def tagged(transaction)
    super(message_header(transaction))
  end

  def message_header(album)
    "< vendor_id: #{transaction.vendor_id}, product_id: #{transaction.product_id}, transaction_id: #{transaction.id} >"
  end
end
```
Here, we re-define each of the severity-level methods to take in a second argument of the `transaction` instance. Then, each of these methods calls on our implementation of the `#tagged` method to format the message header. 

Our custom `#tagged` implementation simply calls on a helper method, `#message_header` to format the tag we want, and goes on to call `super`. 

Each severity-level method calls `#tagged` with a block that contains an invocation of `super`, with an argument of the log statement message that was passed in. Remember that `ActiveSupport::TaggedLogging` delegates the severity-level methods to it's own `logger` instance. When we initialize our `VendorPaymentLogger` we pass in an instance of the standard `Logger` class. So, calling `super` in these severity-level methods will pass the `#info`, `#warn`, etc. method invocation on to the standard logger instance. 

Now that we have our formatter and our tagger behaving properly, we're almost done.

#### Setting the Class-level Logger 

I want to be able to use my custom logger all over my application, wherever the "pay a vendor" code flow takes me. I _don't_ want to have to initialize an instance of `VendorPaymentLogger` each time. I also don't want to set my Rail's app default logger to a `VendorPaymentLogger` instance, because I want the remainder of my application to continue using the default logger. 

We'll solve this problem by teaching the `VendorPaymentLogger` class to respond to the severity-level methods. That way I can call on it like this:

```ruby
VendorPaymentLogger.info("doing a thing now.", transaction)
``` 

We'll define a `logger` attribute on the class level. Then, we'll set `VendorPaymentLogger`'s `logger` attribute to an instance of itself. Lastly, we'll delegate the list of severity-level methods on the class level to the _class's_ logger attribute, i.e. the instance of `VendorPaymentLogger`. Confused yet? Let's take a look:

```ruby
#lib/vendor_payment_logger.rb

class VendorPaymentLogger < ActiveSupport::TaggedLogging
  class << self
    attr_accessor :logger
    delegate :info, :warn, :debug, :error, :to => :logger
  end
  ...
end
```
```ruby
#config/initializers/vendor_payment_logger.rb 

VendorPaymentLogger.logger = VendorPaymentLogger.new(Logger.new("log/vendor_payment.log"))
```
Now we're able to use our custom logger class like this:

```ruby
VendorPaymentLogger.info "initiating bank transfer", transaction

=> 
[INFO 2017-09-08 12:25:2344] <vendor_id: 1234, product_id: 5678, transaction_id: 9101112>
[INFO 2017-09-08 12:25:2344] initiating bank transfer
```
And that's it! Now we can maintain a custom and detailed log regarding vendor payments, with an easy-to-use API.