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

piecehealth · January 28, 2020 · Last by LaoGui replied at June 17, 2020 · 10635 hits
Topic has been selected as the excellent topic by the admin.

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

分享的原则是尽量简单

  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 mark as excellent topic. 28 Jan 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

我们需要的是姿势

You need to Sign in before reply, if you don't have an account, please Sign up first.