How can I log the filename and line number that a log statement occurs when logging with Rails 3.2?

Question

While logging with Rails 3.2, I would like to log the filename and line number a log entry takes place from.

So, if inside my ruby script customer.rb on line 23 I have a log like:

Rails.logger.debug "Debug message"

I want the log to log something like:

[customer.rb:23] Debug message

Is that possible?

Answer 1

I finally figured out that the best solution, that will affect also the log format that other gems that my application is using is the following:

1. Open the class Logger::SimpleFormatter and override the method call. You can do that in an initializing file (config/initializers).
2. Change the method call to log the file and line from the caller[5].

Here is a sample implementation that worked for me:

class Logger::SimpleFormatter
  def call(severity, time, progname, msg)
    call_details = Kernel.caller[5].gsub(/#{Rails.root}/, '')
    call_details.match /(.+):(.+):/
    filename = $1
    line = $2
    length = 40
    filename = "#{filename[-length, filename.length]}" if filename.length >= length
    filename = filename.rjust(length + 2, '.')
    "[#{severity} #{time} #{filename}:#{line}] #{msg}\n"
  end
end

In my solution above, I have also limited the filename to the last 40 characters so that I avoid printing big file paths.

Answer 2

I would experiment with the following lines in the environments configs in config/environments/....rb:

config.log_formatter = proc { |severity, datetime, progname, msg|
  callee = caller[5]                         # get caller from stack
  callee = callee.split('/').last            # remove path from callee info
  callee = callee.split(':')[0, 2].join(':') # remove method name from info

  "[#{callee}] #{msg}\n"
}

Note: It depends on your Rails version where you will find the correct filename and line number in the caller stack. At the time of writing, I found the requested info at caller[5] in the stack, other versions might have it at other positions. Therefore this approach is not very reliable and will certainly break when you update your Rails version in the future.

Problems I see: Is it really helpful just to have the name of a file? How to handle log messages from Rails itself? How to test this to make sure that the position in the stack trace will stay correct in later Rails versions?

Are the filename and line number really good defaults as a logger format? I do not think so.

Answer 3

Of course the easiest solution would be to use __LINE__ and __FILE__ in your code as part of your message, but I presume you want to change the formatting options of your logger. I'm not aware of a direct way to do it in the Logger formatter, however, if you wnat to filter the logs using some custom rules, TaggedLogging in Active upport helps in doing exactly that by stamping log lines with subdomains, request ids, and anything else to aid debugging such applications. Instead of tags you could use __FILE__ and __LINE__ variables here is a example:

logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
logger.tagged("BCX") { logger.info "Stuff" }                            # Logs "[BCX] Stuff"
logger.tagged("BCX", "Jason") { logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
logger.tagged("BCX") { logger.tagged("Jason") { logger.info "Stuff" } } # Logs "[BCX [Jason] Stuff

I also suggest changin the formatter as in the below example:

Log = Logger.new(STDOUT)
  Log.formatter = proc { |severity, datetime, progname, msg|
    "#{severity} #{caller[4]} #{msg}\n"
  }

now each time you call Log.INFO( 'some message') you should have the file and line number of the 'caller' of the log method

Answer 4

Not Rails, but I use a logger like this:

def syn_logger(msg)
  s = 0
  caller.each_with_index { |c, i| s = d if c.include?('syn_logger') }
  puts "#{caller[s]}: #{msg}" #if SYNDICATE_ENV != 'test'                                                                                       
end