Rails [过春节长知识] Rails log 的小知识

piecehealth · 2020年01月28日 · 最后由 LaoGui 回复于 2020年06月17日 · 10635 次阅读
本帖已被管理员设置为精华贴

春节期间大家闲着也是闲着,不如一起分享一些知识来准备年后的面试

分享的原则是尽量简单

  1. 写太详细没人看。
  2. 大家都写简单点,鼓励更多的人参与分享。
  3. 写的简单就看得人多,懂得人少,有利于形成讨论,增加大家参与感。

Request ID 实现

Rails 生产环境的 log 都会带着当前 request id,对 debug 十分有帮助。如

[582284e9-e137-4470-a61c-4c55cdbbc408] Started GET "/pages/index" for ::1 at 2020-01-28 14:38:36 +0800
[582284e9-e137-4470-a61c-4c55cdbbc408] Processing by PagesController#index as HTML
[582284e9-e137-4470-a61c-4c55cdbbc408]   Rendering pages/index.html.erb within layouts/application
[582284e9-e137-4470-a61c-4c55cdbbc408]   Rendered pages/index.html.erb within layouts/application (Duration: 0.0ms | Allocations: 4)
[582284e9-e137-4470-a61c-4c55cdbbc408] Completed 200 OK in 10ms (Views: 8.9ms | ActiveRecord: 0.0ms | Allocations: 4276)
  1. 这个功能是靠config/production.rb中的config.log_tags = [ :request_id ]来开启
  2. Reqeust ID 靠中间件ActionDispatch::RequestId产生,来自请求上游(load balancer, firewall, webserver)赋给请求头headers['X-Request-Id']的值,如果没有则自己生成一个 uuid。
  3. 另一个中间件Rails::Rack::Logger会读到第 1 步的config.log_tags,利用ActiveSupport::TaggedLogging来把request_id加到当前请求的每一行 log 输出。

ActiveSupport::TaggedLogging

ActiveSupport::TaggedLogging很简单,看一眼文档就会使用了

# Wraps any standard Logger object to provide tagging capabilities.
#
#   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"
#
# This is used by the default Rails.logger as configured by Railties to make
# it easy to stamp log lines with subdomains, request ids, and anything else
# to aid debugging of multi-user production applications.

development 环境下 Rails 的 log 是输出到 STDOUT 的吗?

看到ActiveSupport::TaggedLogging的文档,迫不及待打开一个rails console试一下:

2.6.5 :001 > Rails.logger.tagged("武汉") { Rails.logger.info("加油") }
加油
 => true

期望输出是[武汉]加油,但是实际只有加油,但是tag并没有白加。

 $ tail -1 log/development.log
[武汉] 加油

因为 Rails 在 development 环境下实际是输出到log/development.log,在rails console里面能看到Rails.logger输出,实际是因为启动rails console的时候,active_recordRails.logger的输出复制一份并输出到 STDERR 中 (https://github.com/rails/rails/blob/v6.0.2.1/activerecord/lib/active_record/railtie.rb#L58-L61)。

同理,rails server能看到 log 输出,也是因为Rails.logger的输出被复制并输出到 STDOUT 中 (https://github.com/rails/rails/blob/bf625f7fecabbcda22b388e088ad5c29016b2385/railties/lib/rails/commands/server/server_command.rb#L76-L86)。

有时我们会启动一个进程,例如resque worker,会发现开这个进程的终端一点 log 输出也没有,就是上面的原因所致:log 本来就不会往 STDOUT 写。如果想在 STDOUT 中看到 log,参考上面代码,复制Rails.logger输出到 STDOUT 即可

请求结束时最后一条 log 是怎么生成的

当一个请求结束时,默认会有一条汇总的 log

Completed 200 OK in 10ms (Views: 8.9ms | ActiveRecord: 0.0ms | Allocations: 4276)

大部分中小 Rails 应用,ViewsActiveRecord的耗时是大头。但是随着我们业务发展,规模增大,我们应用里耗时部分越来越多,例如 redis 读写,rpc 请求,甚至有同步的外部 http 请求,我们也可以把这些部分的耗时一起写在最后一条 log 中。

由于这条 log 是一个发生在请求中(最后)的 log,所以肯定是ActionController模块生成的。(https://github.com/rails/rails/blob/v6.0.2.1/actionpack/lib/action_controller/log_subscriber.rb#L32-L34)

各个耗时项目的汇总输出,是下面代码完成的

additions = ActionController::Base.log_process_action(payload)
...
message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
message << " (#{additions.join(" | ")})"

ActionController::Base.log_process_action本身的实现只有Views的耗时,但是我们可以通过 overwrite ActionController::Base.log_process_action来添加我们想输出的指标。实际上ActiveRecord就是通过这个方法把自己的耗时加到最后一条 log 里的

参照ActiveRecord::Railties::ControllerRuntime,我们可以把其他指标也输出到最后一条 log 中……如果我们能得到这些指标。

Active Support Instrumentation

Active Support Instrumentation 是中级以上的 Rails 工程师不能不知道的 API。 在开发环境中,我们能看到每个 view render 的时间,每条 database query 执行的时间都是得益于这套 API,是我们在不侵入业务代码的情况下可以得到很多指标,指标包括执行时间。

Rails guide介绍的很清楚,这里就不多介绍。接上面的章节,我们只要实现自己的ActiveSupport::Notifications.instrumentActiveSupport::Notifications.subscribe方法,就可以得到我们想要的指标,配合around_action或者middleware将汇总的指标写到ActionController::Base.log_process_action方法的返回,就可以在自定义最后一条 log 的输出了。

huacnlee 将本帖设为了精华贴。 01月28日 18:36

当时没完全看明白,似乎是:

  1. middleware 生成 request id 后,写到了 thread local variable 中的。

  2. 到了写 log 时,把 thread local variable 中的东西读出来。

我的理解对吗?

request_id 写到当前 request 对象中,差不多

middleware ActionDispatch::RequestId do
    request.request_id = make_request_id

    middleware Rails::Rack::Logger do
        Rails.logger.tagged(request.reqeust_id) do
            # Your Rails Application Code
        end
    end
end

我们需要的是姿势

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