Building a Custom Logger with Active Support Tagged Logging

This post was originally published in my blog, The Great Code Adventure.

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.

source: https://masterofallscience.com (do you guys know about this btw?? some amazing hero made a Rick and Morty gif/meme generator. Strongly recommend.)

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.

[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:

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:

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 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.).

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 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.

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.

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

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:

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

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

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:

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.

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

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:

#lib/vendor_payment_logger.rb

class VendorPaymentLogger < ActiveSupport::TaggedLogging
  class << self
    attr_accessor :logger
    delegate :info, :warn, :debug, :error, :to => :logger
  end
  ...
end

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

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.