Tool for log analysis: Request-log-analyzer
Request-log-analyzer is an amazing tool for log analysis. It helps you understand better the performance and characteristics of your app by providing you insightful information like: request distribution per hour, most popular URIs, traffic summary, time for rendering views and processing database… and many more. At the moment it supports some various kinds of log such as: Amazon S3, Apache, Nginx, Delayed::Job, Merb, Mysql, PostgreSQL, Rails…
What is great with this tool is that it can also parse your logs with a custom format. And this was my case when I needed to analyze a multi-tenancy Rails 4 app, of which production logs contains an additional line in every request to provide information for each tenant. To inspect how the tenants were doing, I had to make some modifications so that request-log-analyzer could understand better the log file. You can read more about this here: https://github.com/wvanbergen/request-log-analyzer/wiki/Creating-your-own-file-format-definition This is a sample for such a request:
I, [2015-04-14T06:44:32.119010 #2217] INFO -- : 200 GET /events.json?category_ids[]=104&status[]=opening&status[]=locked&per_page=100&sort_dir=asc total=109.97 views=32.15 database=44.27 tenant=foo
I, [2015-04-14T06:44:32.859514 #2217] INFO -- : Started GET "/" for 10.130.xxx.xxx at 2015-04-14 06:44:32 +0700
I, [2015-04-14T06:45:41.174304 #2217] INFO -- : Started GET "/events.json?category_ids[]=17&category_ids[]=18&category_ids[]=29&category_ids[]=32&status[]=opening&per_page=100&sort_dir=asc" for 106.187.xxx.xxx at 2015-04-14 06:45:41 +0700
I, [2015-04-14T06:45:41.186927 #2217] INFO -- : Processing by EventsController#index as JSON
I, [2015-04-14T06:45:41.187118 #2217] INFO -- : Parameters: {"category_ids"=>["17", "18", "29", "32"], "status"=>["opening"], "per_page"=>"100", "sort_dir"=>"asc", "event"=>{}}
I, [2015-04-14T06:45:41.577474 #2217] INFO -- : Rendered events/index.json.jbuilder (316.7ms)
I, [2015-04-14T06:45:41.578372 #2217] INFO -- : Completed 200 OK in 391ms (Views: 228.9ms | ActiveRecord: 132.3ms)
As you can see, the request starts with a line in the format of `HTTP_RESPONSE_CODE METHOD PATH total=REQUEST_TOTAL_TIME views=REQUEST_RENDERING_VIEWS_TIME database=REQUEST_DATABASE_TIME tenant=TENANT_NAME`. At first, I thought of writing my own format definition, derived from `class Tenant < RequestLogAnalyzer::FileFormat::Rails`:
class Tenant < RequestLogAnalyzer::FileFormat::Rails
line_definition :current_tenant do |line|
line.regexp = /\d* ?\w+ \/.* total=(\d+[\.\d+]*) views=\d+[\.\d+]* database=\d+[\.\d+]* tenant=(\w+)/
line.capture(:tenant_duration).as(:duration, unit: :msec)
line.capture(:tenant_name)
end
report(:append) do |analyze|
analyze.frequency :tenant_name, :title => "Requests by Tenant"
analyze.duration :tenant_duration, :title => "Duration of tenant request", :category => :tenant_name
end
end
This, however, results to no requests are parsed:
$ request-log-analyzer --format tenant.rb production.log
Request-log-analyzer, by Willem van Bergen and Bart ten Brinke - version 1.13.4
Website: http://railsdoctors.com
production.log: 100% [================================] Time: 00:00:03
Request summary
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Processed File: production.log
Parsed lines: 11606
Skipped lines: 11606
Parsed requests: 0
Skipped requests: 0
Warnings: teaser_check_failed: 11592, no_current_request: 11606
There were no requests analyzed.
Then I discovered that request-log-analyzer doesn’t use the `Rails` file format, it uses `Rails3` instead. But changing the class name from `class Tenant < RequestLogAnalyzer::FileFormat::Rails` to `class Tenant < RequestLogAnalyzer::FileFormat::Rails3` didn’t help either:
$ request-log-analyzer --format tenant.rb production.log
Request-log-analyzer, by Willem van Bergen and Bart ten Brinke - version 1.13.4
Website: http://railsdoctors.com
/Users/minhdanh/.rvm/gems/ruby-2.1.3/gems/request-log-analyzer-1.13.4/lib/request_log_analyzer/controller.rb:252:in `initialize': Invalid file format! (RuntimeError)
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/gems/request-log-analyzer-1.13.4/lib/request_log_analyzer/controller.rb:188:in `new'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/gems/request-log-analyzer-1.13.4/lib/request_log_analyzer/controller.rb:188:in `build'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/gems/request-log-analyzer-1.13.4/lib/request_log_analyzer/controller.rb:91:in `build_from_arguments'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/gems/request-log-analyzer-1.13.4/bin/request-log-analyzer:133:in `<top (required)>'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/bin/request-log-analyzer:23:in `load'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/bin/request-log-analyzer:23:in `<main>'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/bin/ruby_executable_hooks:15:in `eval'
from /Users/minhdanh/.rvm/gems/ruby-2.1.3/bin/ruby_executable_hooks:15:in `<main>'
I had no idea with this error, so I decided to have a look at the class `RequestLogAnalyzer::FileFormat::Rails3` (located in `$GEM_HOME/gems/request-log-analyzer-1.13.4/lib/request_log_analyzer/file_format/rails3.rb`) and made direct modifications on the file. I added some lines:
line_definition :current_tenant do |line|
line.header = true
line.regexp = /\d* ?\w+ \/.* total=(\d+[\.\d+]*) views=\d+[\.\d+]* database=\d+[\.\d+]* tenant=(\w+)/
line.capture(:tenant_duration).as(:duration, unit: :msec)
line.capture(:tenant_name)
end
before `line_definition :started do |line|`, and then removed `line.header = true` in the `line_definition :started do |line|` block. `line.header` is an indicator of the beginning of a request, so it makes sense to mark our line definition `:current_tenant` as request header. Then I appended these 2 lines in the block `report do |analyze|`
analyze.frequency :tenant_name, :title => "Requests by Tenant"
analyze.duration :tenant_duration, :title => "Duration of tenant requests", :category => :tenant_name
I ran the command again without `–format` option, and it worked:
:)