By using lograge / lograge-sql, you can output Rails log and multi-line log such as execution SQL in Json format etc. to make the log easy to see.
lograge lograge is a Gem that can output a single line Log (example: json) by using only the necessary information for the multiple line log of Rails basic Loggger. https://github.com/roidrage/lograge
lograge
{"method":"GET","path":"/xxxxx","format":"html","controller":"Test::TestController","action":"index","status":200,"duration":109.04,"view":80.24,"db":0.0,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007faac342cd70>","view_runtime":80.24499999919499,"db_runtime":0,"custom_payload":{"timestamp":"2020-06-17 08:43:23 +0900","request_id":"25e160cb-1dcb-4b19-8eb2-9253f35b4f93","remote_ip":"127.0.0.1"},"operator_name":"Tester","email":"[email protected]","timestamp":"2020-06-17 08:43:23 +0900","request_id":"25e160cb-1dcb-4b19-8eb2-9253f35b4f93","remote_ip":"127.0.0.1"}
lograge-sql lograge-sql is a lograge extension Gem that outputs SQL to the log https://github.com/iMacTia/lograge-sql
lograge-sql
{
"sql_queries": "name1 ({duration1}) {query1}\nname2 ({duration2}) query2 ...",
"sql_queries_count": 3
}
Let's start with the Rails Tutorial source. https://github.com/yasslab/sample_app
lograge
Gemfile
gem "lograge"
config/environments/develpment.rb
config.lograge.enabled = true
Before using lograge
Started GET "/" for 127.0.0.1 at 2020-06-17 15:01:01 +0900
(0.1ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
↳ /Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
Processing by StaticPagesController#home as HTML
User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 101], ["LIMIT", 1]]
↳ app/helpers/sessions_helper.rb:13
Rendering static_pages/home.html.erb within layouts/application
(0.6ms) SELECT COUNT(*) FROM "microposts" WHERE "microposts"."user_id" = ? [["user_id", 101]]
↳ app/views/shared/_user_info.html.erb:4
Rendered shared/_user_info.html.erb (3.3ms)
(0.5ms) SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."followed_id" WHERE "relationships"."follower_id" = ? [["follower_id", 101]]
↳ app/views/shared/_stats.html.erb:5
(0.5ms) SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."follower_id" WHERE "relationships"."followed_id" = ? [["followed_id", 101]]
↳ app/views/shared/_stats.html.erb:11
Rendered shared/_stats.html.erb (16.1ms)
Rendered shared/_error_messages.html.erb (0.6ms)
Rendered shared/_micropost_form.html.erb (13.9ms)
(0.2ms) SELECT COUNT(*) FROM "microposts" WHERE (user_id = 101)
↳ app/views/shared/_feed.html.erb:1
Rendered shared/_feed.html.erb (1.3ms)
Rendered static_pages/home.html.erb within layouts/application (46.9ms)
Rendered layouts/_shim.html.erb (0.4ms)
Rendered layouts/_header.html.erb (1.0ms)
Rendered layouts/_footer.html.erb (0.4ms)
Completed 200 OK in 610ms (Views: 543.5ms | ActiveRecord: 3.2ms)
After using lograge
(0.2ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
↳ /Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 101], ["LIMIT", 1]]
↳ app/helpers/sessions_helper.rb:13
(7.0ms) SELECT COUNT(*) FROM "microposts" WHERE "microposts"."user_id" = ? [["user_id", 101]]
↳ app/views/shared/_user_info.html.erb:4
(0.4ms) SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."followed_id" WHERE "relationships"."follower_id" = ? [["follower_id", 101]]
↳ app/views/shared/_stats.html.erb:5
(0.4ms) SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."follower_id" WHERE "relationships"."followed_id" = ? [["followed_id", 101]]
↳ app/views/shared/_stats.html.erb:11
(0.1ms) SELECT COUNT(*) FROM "microposts" WHERE (user_id = 101)
↳ app/views/shared/_feed.html.erb:1
method=GET path=/ format=html controller=StaticPagesController action=home status=200 duration=663.54 view=564.69 db=9.17
The connection result of Root parsing is output in one line on the last line
** If you want to output in Json format, add the following **
config/environments/develpment.rb
config.lograge.formatter = Lograge::Formatters::Json.new
The result of connecting to Root is displayed in Json format.
Json format
{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":200,"duration":694.98,"view":592.73,"db":3.04}
** Add Hook to customize your log **
Added config.lograge.custom_options
config/environments/develpment.rb
config.lograge.custom_options = ->(event) {
exceptions = %w(controller action format authenticity_token)
payload = event.payload
payload[:params] = payload[:params].except(*exceptions) #controller,Eliminate action name
#If an exception occurs, output Exception and backtrace
if payload[:exception]
payload[:exception] = payload[:exception]
payload[:exception_backtrace] = payload[:exception_object].backtrace[0..6]
end
payload
}
Raise Exception to controller
static_pages_controller.rb
def home
raise "error"
end
Rogue after Root connection
Before adding Hook (StaticPagesController)
{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":500,"error":"RuntimeError: error","duration":6.77,"view":0.0,"db":0.0,"sql_queries":"' (0.13) SELECT \"schema_migrations\".\"version\" FROM \"schema_migrations\" ORDER BY \"schema_migrations\".\"version\" ASC'","sql_queries_count":1}
With the addition of Hook, exception and exception_backtrace have been added.
After adding Hook
{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":500,"error":"RuntimeError: error","duration":0.51,"view":0.0,"db":0.0,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007f8ed7971e78>","view_runtime":null,"db_runtime":0,"exception":["RuntimeError","error"],"exception_object":"error","exception_backtrace":["/Users/xxxx/Desktop/ruby/sample_app/app/controllers/static_pages_controller.rb:9:in `home'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:194:in `process_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:30:in `process_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:132:in `run_callbacks'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'"]}
** Add items to Payload by Overriding the append_info_to_payload function to Controller **
StaticPagesController
class StaticPagesController < ApplicationController
def append_info_to_payload(payload)
super
payload[:host] = request.host
end
end
Host information has been added " host ":" localhost "
After addition
{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":200,"duration":1321.96,"view":1148.47,"db":3.28,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007fc6e8869d98>","view_runtime":1148.4679999998662,"db_runtime":3.281999999217078,"host":"localhost","sql_queries":"' (0.27) SELECT \"schema_migrations\".\"version\" FROM \"schema_migrations\" ORDER BY \"schema_migrations\".\"version\" ASC\nUser Load (0.51) SELECT \"users\".* FROM \"users\" WHERE \"users\".\"id\" = ? LIMIT ?\n (0.4) SELECT COUNT(*) FROM \"microposts\" WHERE \"microposts\".\"user_id\" = ?\n (0.51) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"followed_id\" WHERE \"relationships\".\"follower_id\" = ?\n (0.42) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"follower_id\" WHERE \"relationships\".\"followed_id\" = ?\n (0.15) SELECT COUNT(*) FROM \"microposts\" WHERE (user_id = 101)'","sql_queries_count":6}
lograge-sql
Gemfile
gem "lograge-sql"
config/initializers/lograge.rb
require 'lograge/sql/extension'
I was able to confirm that sql_queries and sql_queries_count were added.
result
{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":200,"duration":93.2,"view":84.45,"db":0.76,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007fedb15158a0>","view_runtime":84.45099999994454,"db_runtime":0.7550000000264845,"sql_queries":"'User Load (0.13) SELECT \"users\".* FROM \"users\" WHERE \"users\".\"id\" = ? LIMIT ?\n (0.14) SELECT COUNT(*) FROM \"microposts\" WHERE \"microposts\".\"user_id\" = ?\n (0.14) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"followed_id\" WHERE \"relationships\".\"follower_id\" = ?\n (0.18) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"follower_id\" WHERE \"relationships\".\"followed_id\" = ?\n (0.16) SELECT COUNT(*) FROM \"microposts\" WHERE (user_id = 101)'","sql_queries_count":5}
develpment.rb
config.lograge.logger = ActiveSupport::Logger.new(STDOUT)
Log output
output
Lograge.logger.info({ type: 'type', exception: 'exception'}.to_json)
lograge source reference https://github.com/roidrage/lograge/blob/1729eab7956bb95c5992e4adab251e4f93ff9280/lib/lograge.rb#L185
Recommended Posts