Add structured logging for Rails processes
This introduces JSON logging for Rails views saved to a file called
`development_json.log`, `production_json.log`, etc.
For example, instead of this unparsable log:
```
Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
Rendered text template within layouts/application (0.0ms)
Rendered layouts/_assets.html.erb (2.0ms)
Rendered layouts/_top.html.erb (2.6ms)
Rendered layouts/_about.html.erb (0.3ms)
Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
```
We get a single line with this:
```
{"method":"GET","path":"/,"format":"html","controller":"HomeController","action":"index","status":200,"duration":79,"view":78.8,"db":0.0,"location":"http://localhost/","time":"2017-07-18 09:35:17 -0700"}
```
Part of #20060
2017-07-17 18:54:13 -04:00
|
|
|
# Only use Lograge for Rails
|
|
|
|
unless Sidekiq.server?
|
|
|
|
filename = File.join(Rails.root, 'log', "#{Rails.env}_json.log")
|
|
|
|
|
|
|
|
Rails.application.configure do
|
|
|
|
config.lograge.enabled = true
|
|
|
|
# Store the lograge JSON files in a separate file
|
|
|
|
config.lograge.keep_original_rails_log = true
|
|
|
|
# Don't use the Logstash formatter since this requires logstash-event, an
|
|
|
|
# unmaintained gem that monkey patches `Time`
|
|
|
|
config.lograge.formatter = Lograge::Formatters::Json.new
|
|
|
|
config.lograge.logger = ActiveSupport::Logger.new(filename)
|
|
|
|
# Add request parameters to log output
|
|
|
|
config.lograge.custom_options = lambda do |event|
|
2018-02-28 10:45:41 -05:00
|
|
|
params = event.payload[:params]
|
|
|
|
.except(*%w(controller action format))
|
|
|
|
.each_pair
|
|
|
|
.map { |k, v| { key: k, value: v } }
|
|
|
|
|
2017-09-19 06:55:37 -04:00
|
|
|
payload = {
|
2019-06-25 13:54:42 -04:00
|
|
|
time: Time.now.utc.iso8601(3),
|
2018-02-28 10:45:41 -05:00
|
|
|
params: params,
|
2017-07-28 01:48:03 -04:00
|
|
|
remote_ip: event.payload[:remote_ip],
|
|
|
|
user_id: event.payload[:user_id],
|
2018-09-05 17:40:36 -04:00
|
|
|
username: event.payload[:username],
|
2019-02-10 19:43:44 -05:00
|
|
|
ua: event.payload[:ua],
|
|
|
|
queue_duration: event.payload[:queue_duration]
|
Add structured logging for Rails processes
This introduces JSON logging for Rails views saved to a file called
`development_json.log`, `production_json.log`, etc.
For example, instead of this unparsable log:
```
Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
Rendered text template within layouts/application (0.0ms)
Rendered layouts/_assets.html.erb (2.0ms)
Rendered layouts/_top.html.erb (2.6ms)
Rendered layouts/_about.html.erb (0.3ms)
Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
```
We get a single line with this:
```
{"method":"GET","path":"/,"format":"html","controller":"HomeController","action":"index","status":200,"duration":79,"view":78.8,"db":0.0,"location":"http://localhost/","time":"2017-07-18 09:35:17 -0700"}
```
Part of #20060
2017-07-17 18:54:13 -04:00
|
|
|
}
|
2017-09-19 06:55:37 -04:00
|
|
|
|
2019-08-09 00:33:20 -04:00
|
|
|
::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
|
2019-07-17 19:34:27 -04:00
|
|
|
|
2018-06-06 03:47:53 -04:00
|
|
|
payload[:response] = event.payload[:response] if event.payload[:response]
|
2019-02-18 15:57:22 -05:00
|
|
|
payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
|
2017-09-19 06:55:37 -04:00
|
|
|
|
2019-10-17 14:08:05 -04:00
|
|
|
if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.start_thread_cpu_time)
|
|
|
|
payload[:cpu_s] = cpu_s
|
|
|
|
end
|
|
|
|
|
2017-09-19 06:55:37 -04:00
|
|
|
payload
|
Add structured logging for Rails processes
This introduces JSON logging for Rails views saved to a file called
`development_json.log`, `production_json.log`, etc.
For example, instead of this unparsable log:
```
Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
Rendered text template within layouts/application (0.0ms)
Rendered layouts/_assets.html.erb (2.0ms)
Rendered layouts/_top.html.erb (2.6ms)
Rendered layouts/_about.html.erb (0.3ms)
Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
```
We get a single line with this:
```
{"method":"GET","path":"/,"format":"html","controller":"HomeController","action":"index","status":200,"duration":79,"view":78.8,"db":0.0,"location":"http://localhost/","time":"2017-07-18 09:35:17 -0700"}
```
Part of #20060
2017-07-17 18:54:13 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
end
|