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

分享的原则是尽量简单

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_record让Rails.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 应用，Views与ActiveRecord的耗时是大头。但是随着我们业务发展，规模增大，我们应用里耗时部分越来越多，例如 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
• ActiveRecord::Railtie

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

Active Support Instrumentation

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

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