Rails 简记 Rails 中的 logger 实用技巧

pathbox · 2017年12月02日 · 最后由 martin91 回复于 2018年03月22日 · 11621 次阅读
本帖已被管理员设置为精华贴
Gem lograge

lograge is awesome for formating log.


# Gemfile
gem "lograge"
# config/initializers/lograge.rb
# OR
# config/environments/production.rb

Rails.application.configure do
  ...
# Logger
  config.lograge.enabled = true
  config.lograge.ignore_actions = ['home#welcome']
  config.lograge.custom_options = lambda do |event|
    params = event.payload[:params].reject do |k|
      ['controller', 'action'].include? k
    end
    options = {
      params: params,    # add params to lograge
      time:   event.time # add time to lograge
    }
    options
  end
  ...
end

lograge 能帮你格式化日志输出,定义日志输出的格式和内容。去掉了 view 层渲染的日志内容。如果你不需要日志具体打印 view 层的渲染内容,用lograge是极好的,如果你需要,lograge 就不适合你。一般应用不关心 view 层渲染的具体日志内容。

例子:

环境:Rails 5.1.4

lograge还提供了不同的 formatters。

Lograge::Formatters::Lines.new
Lograge::Formatters::Cee.new
Lograge::Formatters::Graylog2.new
Lograge::Formatters::KeyValue.new  # default lograge format
Lograge::Formatters::Json.new
Lograge::Formatters::Logstash.new
Lograge::Formatters::LTSV.new
Lograge::Formatters::Raw.new       # Returns a ruby hash object

默认的日志格式是 key=value 的格式:

[2017-12-01 22:43:00] [INFO] [] [localhost] [127.0.0.1] [1593754b-bc95-42] method=GET path=/ format=*/* controller=HomeController action=welcome status=200 duration=472.00 view=0.00 params={} time=2017-12-01 11:49:09 +0800

比如,配置 Lograge::Formatters::Json.new

config.lograge.formatter = Lograge::Formatters::Json.new

得到的日志结果是这样的:

[2017-12-01 22:43:34] [INFO] [] [localhost] [127.0.0.1] [74cc1bef-2155-42] {"method":"GET","path":"/","format":"*/*","controller":"HomeController","action":"welcome","status":200,"duration":3.09,"view":0.0,"params":{"home":{}},"time":"2017-12-01 22:43:34 +0800"}
config.lograge.formatter = Lograge::Formatters::Graylog2.new

得到的日志结果是这样的:

[2017-12-01 22:47:46] [INFO] [] [localhost] [127.0.0.1] [18654bb8-01ec-48] {:_method=>"GET", :_path=>"/", :_format=>"*/*", :_controller=>"HomeController", :_action=>"welcome", :_status=>200, :_duration=>368.34, :_view=>0.0, :_params=>{"home"=>{}}, :_time=>2017-12-01 22:47:46 +0800, :short_message=>"[200] GET / (HomeController#welcome)"}

如果想使用

config.lograge.formatter = Lograge::Formatters::Logstash.new

需要配合安装 logstash-event

gem "logstash-event"

这样很方便的能够得到你想要的日志内容结构,并且被各种日志监控系统兼容。这是lograge简单的功能,更多配置查看文档

自定义生成 log 文件

有时候,我们想要将日志存储到一个新的 log 文件中,和主日志文件区分开来。

定义一个类方法或全局的方法:

def create_my_logger(file_name)
  logger = Logger.new("#{Rails.root}/log/#{file_name}")  # 根据file_name,创建一个logger实例。会在Rails.root/log目录下生成file_name文件,用来记录日志
  logger.level = Logger::DEBUG  # 设置日志的level
  logger.formatter = proc do |severity, datetime, progname, message| # 设置日志的formatter
    "[#{datetime.to_s(:db)}] [#{severity}] #{message}\n"
  end

  logger
end

在想要使用该日志实例的代码中:

log = create_my_logger("third_api_service.log")

... # do something
result = do_third_api_service
if result
  log.info("Third api service success")
else
  log.error("Third api service fail: #{result}")
end

个人认为这种方法适用于调用一些关键服务或操作,想要快速了解该服务的正确性,当有错误的时候,可以快速查阅日志,了解服务信息。也便于调试和快速排查问题

还可以给 logger 实例扩展一些方法:

module MyLogger
  def log_json
    info = {}
    title = []

    yield msg, info

    timestamp  = Time.now.strftime('%Y%m%d_%H%M%S_%L')
    msg      = [timestamp, msg].flatten.compact
    title = title.join('-')

    data = {}
    data[:msg] = msg
    data.merge! info

    self.debug data.to_json # 打印json日志内容
  end
end

def create_my_logger(file_name)
  logger = Logger.new("#{Rails.root}/log/#{file_name}")  # 根据file_name,创建一个logger实例。会在Rails.root/log目录下生成file_name文件,用来记录日志
  logger.level = Logger::DEBUG  # 设置日志的level
  logger.formatter = proc do |severity, datetime, progname, message| # 设置日志的formatter
    "[#{datetime.to_s(:db)}] [#{severity}] #{message}\n"
  end
  logger.extend MyLogger

  logger
end

使用示例:

SYNC_LOGGER = create_my_logger('sync.log')

SYNC_LOGGER.log_json do |msg, info|
  msg << 'user_id:1'
  info[:action] = 'sync success'
end

生成 sync.log 文件会打印以下信息:

[2017-12-01 22:45:20] [DEBUG] {"title":"20171202_141419_311-user_id:1","action":"sync success"}
为调用外部服务增加必要日志

当系统中有需要 http client 形式调用外部服务时,比如:微信开发的微信接口,推送接口,第三方开放 API,我会这么做:

使用示例:

API_LOGGER = create_my_logger('xxx_api.log')

API_LOGGER.log_json do |msg, info|
  begin
    msg << 'xxx:api:user_id:1'
    info[:resquest] = request_params
    start = Time.now
    res = httpclient.do(url, request_params)
    duration = Time.now - start
    info[:response] = res
    info[:duration] = duration
    info[:error] = nil
  rescue => e
    info[:res] = nil
    info[:error] = "#{e.inspect}"
  end
end

请求参数返回响应报错信息都记录下来,查看日志时一目了然。出问题时,能帮助你很快的定位出是系统中的 bug 还是外部服务的 bug。

证明"代码的清白",就靠他们了。

一个好的日志设计和使用习惯,是一个系统稳定、健壮和可控的重要保证。

本文简单小结了在 Rails 项目中日志的使用。

huacnlee 将本帖设为了精华贴。 12月04日 10:57

小心丢日志。

ruby_sky 回复

啥意思?比如?

不错的实践!学起来!

log 给我的最大用途就是 debug。。。哈哈

内容很不错,就是标题有点不确切,《简记 Rails 中的 logger 实用技巧》,第一反应以为你说的是 Ruby 内置 Logger 和 Rails 扩展的 ActiveSupport::Logger 呢,但是文章讲的都是 lograge 这个 gem 的使用,是不是《Rails 结合 lograge 优化日志输出》会更贴切呢?仅为个人拙见。

需要 登录 后方可回复, 如果你还没有账号请 注册新账号