Enabling a custom formatter in Rails

Question

I've written a custom formatter for Rails:

module Logging
  class GeneralFormatter < Logger::Formatter
    def call(severity, time, program_name, message)
      ...
    end
  end
end

And according to the Rails guide and this answer, all I have to do to use it is set

config.log_formatter = Logging::GeneralFormatter.new

Unfortunately, this doesn't seem to work—my custom formatting isn't kicking in. And yet, if I instead define this as well:

module Logging
  class GeneralLogger < ActiveSupport::Logger
    def initialize(*args)
      super(*args)
      @formatter = GeneralFormatter.new
    end
  end
end

Then I can do config.logger = Logging::GeneralLogger.new and my logs are formatted as desired.

What am I doing wrong with setting log_formatter? I'd rather not define my own Logger when all I want is custom formatting.

---

EDIT (responding to comments, and adding more detail from a little more digging):

I'm setting config.log_formatter in application.rb and it testing in development, and it appears to be working to an extent, in that calling Rails.logger.formatter gives me my custom class. But here's the behavior I'm seeing on calling Rails.logger.warn("test"):

1. test is printed out to the console (followed by a newline).
2. Then the call method of my formatter is entered.
3. The return value of the call method is never printed out to the console.

Where what I thought would happen (and what I want to happen is):

1. The call method of my formatter is entered.
2. The return value of the call method is printed out to the console.
3. Nothing else is printed.

Am I misunderstanding how formatters work?

---

EDIT Again (providing clearer example):

When I have this defined:

def call(severity, time, program_name, message)
  puts "Checkpoint 1"
  "Checkpoint 2"
end

and call Rails.logger.warn("Checkpoint 0"), I expect to see:

Checkpoint 1
Checkpiont 2

but instead I see:

Checkpoint 0
Checkpoint 1

Answer 1

Okay, let's try again.

I don't actually have an answer -- instead, I am unable to reproduce your problem. I will give you the steps I took and what I saw, perhaps you will be able to compare to what you've done to see how it's different.

• You didn't say what version of Rails you have, I started with the latest 4.1.1. Built a brand new application rails new logtest.

Added a file at ./lib/custom_formatter.rb that looks like this:

class CustomFormatter < Logger::Formatter
  def call(severity, time, program_name, message)
    # I think it makes no sense to have a raw `puts`
    # in a log formatter, but I'll leave it in to
    # copy you. Almost certainly a bad idea though. 
    # commented out. 
    puts "Checkpoint 1"
    return "Checkpoint 2"
  end
end

Added this to my existing config/application.rb:

require 'custom_formatter'
config.log_formatter = CustomFormatter.new

Now I start up the application with rails server, and access http://localhost:3000/test. I expect to get an error message, because I haven't defined any routes or controllers or anything. But because of my weird custom logger, I expect all the log lines to be essentially replaced by "Checkpoint 1" and "Checkpoint 2". Indeed that's what's happened. My console looks like this:

  [2014-06-03 18:22:49] INFO  WEBrick 1.3.1
  [2014-06-03 18:22:49] INFO  ruby 1.9.3 (2013-02-22) [x86_64-darwin12.2.1]
  [2014-06-03 18:22:49] INFO  WEBrick::HTTPServer#start: pid=57113 port=3000
  Checkpoint 1
  Checkpoint 2Checkpoint 1
  Checkpoint 1
  Checkpoint 2Checkpoint 1
  Checkpoint 1
  Checkpoint 2Checkpoint 1
  Checkpoint 1
  Checkpoint 2Checkpoint 1
  Checkpoint 1
  Checkpoint 2Checkpoint 1
  Checkpoint 1
  Checkpoint 2Checkpoint 1
  Checkpoint 1
  Checkpoint 2Checkpoint 1

My development.log looks like this:

  Checkpoint 2Checkpoint 2Checkpoint 2Checkpoint 2Checkpoint 2Checkpoint 2Checkpoint 2

So clearly that custom 'formatter' isn't doing anything useful -- and I strongly recommend against putting a straight 'puts' line in a real formatter.

But my custom formatter is indeed being used, all log lines are 'formatted' as the fixed string 'Checkpoint 2' (with no newline at the end!), and the additional "Checkpoint 1" is also puts to stdout.

So your problem is not reproducible by the steps you've given, if I try to do what you say you've done, I dont' have your problem. So, this is indeed how debugging works, it is frustrating! I suggest you follow my steps to create a test app above and see if it works for you too. Then you've got to compare your actual app to that little test app and figure out how it's different, to manifest the problem in your actual app. One common way to do this is make a copy of your actual app, and begin stripping out everything you can, to get the barest possible app that still manifests the problem. Odds are, in doing this, you'll figure out yourself the cause of the problem -- but if you don't, you can make your bare bones demonstration app available to others trying to help you, and they can maybe figure out what in it is causing the problem.