diff --git a/.ruby-gemset b/.ruby-gemset new file mode 100644 index 00000000..d463fe17 --- /dev/null +++ b/.ruby-gemset @@ -0,0 +1 @@ +request-log-analyzer diff --git a/.ruby-version b/.ruby-version new file mode 100644 index 00000000..c063f5a8 --- /dev/null +++ b/.ruby-version @@ -0,0 +1 @@ +ruby-2.2.4 diff --git a/lib/request_log_analyzer/file_format.rb b/lib/request_log_analyzer/file_format.rb index 53489bac..c703ad77 100644 --- a/lib/request_log_analyzer/file_format.rb +++ b/lib/request_log_analyzer/file_format.rb @@ -3,6 +3,7 @@ module RequestLogAnalyzer::FileFormat autoload :Rails, 'request_log_analyzer/file_format/rails' autoload :Rails3, 'request_log_analyzer/file_format/rails3' + autoload :Rails3Solr, 'request_log_analyzer/file_format/rails3_solr' autoload :RailsDevelopment, 'request_log_analyzer/file_format/rails_development' autoload :Oink, 'request_log_analyzer/file_format/oink' autoload :Rack, 'request_log_analyzer/file_format/rack' @@ -210,6 +211,12 @@ def self.line_definition(name, &block) line_definer.define_line(name, &block) end + def self.extend_line_definition(name, &block) + line_definition = line_definer.line_definitions[name] + raise StandardError.new("#{name} has not been defined as line definition. Use +line_definition+ to define it.") if line_definition.nil? + yield(line_definition) + end + # Specifies multiple line definitions at once using a block def self.format_definition(&_block) if block_given? diff --git a/lib/request_log_analyzer/file_format/rails3.rb b/lib/request_log_analyzer/file_format/rails3.rb index 08f04a90..3d14f4d2 100644 --- a/lib/request_log_analyzer/file_format/rails3.rb +++ b/lib/request_log_analyzer/file_format/rails3.rb @@ -41,7 +41,7 @@ class Rails3 < Base line_definition :completed do |line| line.footer = true line.teaser = /Completed / - line.regexp = /Completed (\d+)? .*in (\d+(?:\.\d+)?)ms(?:[^\(]*\(Views: (\d+(?:\.\d+)?)ms .* ActiveRecord: (\d+(?:\.\d+)?)ms.*\))?/ + line.regexp = /Completed (\d+)? .*in (\d+(?:\.\d+)?)ms(?:[^\(]*\(Views: (\d+(?:\.\d+)?)ms(?:.* ActiveRecord: (\d+(?:\.\d+)?)ms)?.*\))?/ line.capture(:status).as(:integer) line.capture(:duration).as(:duration, unit: :msec) @@ -97,6 +97,7 @@ class Rails3 < Base analyze.duration :partial_duration, category: :rendered_file, title: 'Partials rendering time', line_type: :rendered analyze.duration :view, category: REQUEST_CATEGORIZER, title: 'View rendering time', line_type: :completed analyze.duration :db, category: REQUEST_CATEGORIZER, title: 'Database time', line_type: :completed + analyze.duration :solr, category: REQUEST_CATEGORIZER, title: 'Solr time', line_type: :completed analyze.frequency category: REQUEST_CATEGORIZER, title: 'Process blockers (> 1 sec duration)', if: lambda { |request| request[:duration] && request[:duration] > 1.0 } diff --git a/lib/request_log_analyzer/file_format/rails3_solr.rb b/lib/request_log_analyzer/file_format/rails3_solr.rb new file mode 100644 index 00000000..7475479b --- /dev/null +++ b/lib/request_log_analyzer/file_format/rails3_solr.rb @@ -0,0 +1,9 @@ +module RequestLogAnalyzer::FileFormat + class Rails3Solr < RequestLogAnalyzer::FileFormat::Rails3 + extend_line_definition :completed do |line| + # Completed 200 OK in 43.2ms (Views: 2.3ms | ActiveRecord: 25.0ms | Solr: 89.5ms) + line.regexp = /Completed (\d+)? .*in (\d+(?:\.\d+)?)ms(?:[^\(]*\(Views: (\d+(?:\.\d+)?)ms(?:.* ActiveRecord: (\d+(?:\.\d+)?)ms)?(?:.* Solr: (\d+(?:\.\d+)?)ms)?.*\))?/ + line.capture(:solr).as(:duration, unit: :msec) + end + end +end \ No newline at end of file diff --git a/spec/unit/file_format/rails3_format_spec.rb b/spec/unit/file_format/rails3_format_spec.rb index 5c753bbf..dcda734e 100644 --- a/spec/unit/file_format/rails3_format_spec.rb +++ b/spec/unit/file_format/rails3_format_spec.rb @@ -75,7 +75,7 @@ it 'should parse :completed lines correctly when ActiveRecord is not mentioned' do line = 'Completed 200 OK in 364ms (Views: 31.4ms)' - subject.should parse_line(line).as(:completed).and_capture(duration: 0.364, status: 200) + subject.should parse_line(line).as(:completed).and_capture(duration: 0.364, status: 200, view: 0.0314) end it 'should parse :completed lines correctly when other durations are specified' do diff --git a/spec/unit/file_format/rails3_solr_format_spec.rb b/spec/unit/file_format/rails3_solr_format_spec.rb new file mode 100644 index 00000000..5fe41290 --- /dev/null +++ b/spec/unit/file_format/rails3_solr_format_spec.rb @@ -0,0 +1,177 @@ +# encoding: utf-8 +require 'spec_helper' + +describe RequestLogAnalyzer::FileFormat::Rails3Solr do + + subject { RequestLogAnalyzer::FileFormat.load(:rails3_solr) } + + it { should be_well_formed } + + it { should satisfy { |ff| ff.report_trackers.length == 11 } } + + describe '#parse_line' do + + it 'should parse :started lines correctly' do + line = 'Started GET "/queries" for 127.0.0.1 at Thu Feb 25 16:15:18 -0800 2010' + subject.should parse_line(line).as(:started).and_capture(method: 'GET', + path: '/queries', ip: '127.0.0.1', timestamp: 20_100_225_161_518) + end + + it 'should parse :started lines in Oct, Nov and Dec correctly' do + line = 'Started GET "/queries" for 127.0.0.1 at Thu Oct 25 16:15:18 -0800 2010' + subject.should parse_line(line).as(:started).and_capture(method: 'GET', + path: '/queries', ip: '127.0.0.1', timestamp: 20_101_025_161_518) + end + + it 'should parse :started lines in Ruby 1.9.2 format correctly' do + line = 'Started GET "/queries" for 127.0.0.1 at 2010-10-26 02:27:15 +0000' + subject.should parse_line(line).as(:started).and_capture(method: 'GET', + path: '/queries', ip: '127.0.0.1', timestamp: 20_101_026_022_715) + end + + it 'should parse :processing lines correctly' do + line = ' Processing by QueriesController#index as HTML' + subject.should parse_line(line).as(:processing).and_capture( + controller: 'QueriesController', action: 'index', format: 'HTML') + end + + it 'should parse nested :processing lines correctly' do + line = ' Processing by Projects::QueriesController#index as HTML' + subject.should parse_line(line).as(:processing).and_capture( + controller: 'Projects::QueriesController', action: 'index', format: 'HTML') + end + + it 'should parse :processing lines correctly with format */*' do + line = ' Processing by ProjectsController#avatar as */*' + subject.should parse_line(line).as(:processing).and_capture( + controller: 'ProjectsController', action: 'avatar', format: '*/*') + end + + it 'should parse :processing lines correctly without format' do + line = ' Processing by ProjectsController#avatar as ' + subject.should parse_line(line).as(:processing).and_capture( + controller: 'ProjectsController', action: 'avatar', format: '') + end + + it 'should parse a :parameters line correctly' do + line = ' Parameters: {"action"=>"cached", "controller"=>"cached"}' + subject.should parse_line(line).as(:parameters).and_capture(params: { action: 'cached', controller: 'cached' }) + end + + it 'should parse a :parameters line with no indentation correctly' do + line = 'Parameters: {"action"=>"cached", "controller"=>"cached"}' + subject.should parse_line(line).as(:parameters).and_capture(params: { action: 'cached', controller: 'cached' }) + end + + it 'parses a :parameters line with file upload correctly' do + line = 'Parameters: {"utf8"=>"✓", "authenticity_token"=>"eqHyMOSSzw35utH4nN+l28mRMdsHUbRxqh+hSMjag0w=", "user"=>{"photo"=>#>}, "commit"=>"speichern"}' + subject.should parse_line(line).as(:parameters).and_capture(:params => {:utf8 => "\u2713", :authenticity_token => "eqHyMOSSzw35utH4nN+l28mRMdsHUbRxqh+hSMjag0w=", :user => {"photo"=>"ActionDispatch::Http::UploadedFile:0x000000068fb190 @original_filename=\"IMG_2228.JPG\", @content_type=\"image/jpeg\", @headers=\"Content-Disposition: form-data; name=\"user[photo]\"; filename=\"IMG_2228.JPG\"\r\nContent-Type: image/jpeg\r\n\", @tempfile=\"File:/tmp/RackMultipart20141010-19270-zah6b7\""}, :commit => "speichern"}) + end + + it 'should parse :completed lines correctly' do + line = 'Completed 200 OK in 170ms (Views: 78.0ms | ActiveRecord: 48.2ms | Solr: 2.5ms)' + subject.should parse_line(line).as(:completed).and_capture( + duration: 0.170, view: 0.078, db: 0.0482, status: 200, solr: 0.0025) + end + + it 'should parse :completed lines correctly when ActiveRecord and Solr are not mentioned' do + line = 'Completed 200 OK in 364ms (Views: 31.4ms)' + subject.should parse_line(line).as(:completed).and_capture(duration: 0.364, status: 200, view: 0.0314) + end + + it 'should parse :completed lines correctly when ActiveRecord is not mentioned' do + line = 'Completed 200 OK in 364ms (Views: 31.4ms | Solr: 8.5ms)' + subject.should parse_line(line).as(:completed).and_capture(duration: 0.364, status: 200, view: 0.0314, solr: 0.0085) + end + + it 'should parse :completed lines correctly when other durations are specified' do + line = 'Completed 200 OK in 384ms (Views: 222.0ms | ActiveRecord: 121.0ms | Solr: 2.8ms | Sphinx: 0.0ms)' + subject.should parse_line(line).as(:completed).and_capture(duration: 0.384, view: 0.222, + db: 0.121, status: 200, solr: 0.0028 ) + end + + it 'should parse :routing_error lines correctly' do + line = "ActionController::RoutingError (No route matches [GET] \"/static/faq\"):" + subject.should parse_line(line).as(:routing_errors).and_capture(missing_resource_method: 'GET', + missing_resource: '/static/faq') + end + + it 'should parse :failure lines correctly' do + line = "ActionView::Template::Error (undefined local variable or method `field' for #) on line #3 of /Users/willem/Code/warehouse/app/views/queries/execute.csv.erb:" + subject.should parse_line(line).as(:failure).and_capture(line: 3, + error: 'ActionView::Template::Error', + message: "undefined local variable or method `field' for #", + file: '/Users/willem/Code/warehouse/app/views/queries/execute.csv.erb') + end + + it 'should parse :rendered lines as an array' do + line = ' Rendered queries/index.html.erb (0.6ms)' + subject.should parse_line(line).as(:rendered).and_capture(partial_duration: [0.0006]) + end + + it 'should parse :rendered lines with no identation as an array' do + line = 'Rendered queries/index.html.erb (0.6ms)' + subject.should parse_line(line).as(:rendered).and_capture(partial_duration: [0.0006]) + end + end + + describe '#parse_io' do + let(:log_parser) { RequestLogAnalyzer::Source::LogParser.new(subject) } + + it 'should parse a successful request correctly' do + log = <<-EOLOG + Started GET "/" for 127.0.0.1 at Fri Mar 19 06:40:41 -0700 2010 + Processing by QueriesController#index as HTML + SQL (16.3ms) SHOW TABLES + Query Load (32.0ms) SELECT `queries`.* FROM `queries` + Rendered queries/index.html.erb within layouts/default (40.9ms) + Completed 200 OK in 170ms (Views: 78.4ms | ActiveRecord: 48.2ms) + EOLOG + + log_parser.should_receive(:handle_request).once + log_parser.should_not_receive(:warn) + log_parser.parse_string(log) + end + + it 'should count partials correctly' do + log = <<-EOLOG + Started GET "/stream_support" for 127.0.0.1 at 2012-11-21 15:21:31 +0100 + Processing by HomeController#stream_support as */* + Rendered home/stream_support.html.slim (33.2ms) + Rendered home/stream_support.html.slim (0.0ms) + Completed 200 OK in 2ms (Views: 0.6ms | ActiveRecord: 0.0ms) + EOLOG + + log_parser.parse_string(log) + end + + it 'should parse a failing request correctly' do + log = <<-EOLOG + Started POST "/queries/397638749/execute.csv" for 127.0.0.1 at Mon Mar 01 18:44:33 -0800 2010 + Processing by QueriesController#execute as CSV + Parameters: {"commit"=>"Run query", "authenticity_token"=>"pz9WcxkcrlG/43eg6BgSAnJL7yIsaffuHbYxPHUsUzQ=", "id"=>"397638749"} + + ActionView::Template::Error (undefined local variable or method `field' for #) on line #3 of /Users/application/app/views/queries/execute.csv.erb: + 1: <%=raw @result.fields.map { |f| f.humanize.to_json }.join(',') %> + 2: <% @result.each do |record| %> + 3: <%=raw @result.fields.map { |f| record[field].to_s }.join(",") %> + 4: <% end %> + + app/views/queries/execute.csv.erb:3:in `_render_template__652100315_2182241460_0' + app/views/queries/execute.csv.erb:3:in `map' + app/views/queries/execute.csv.erb:3:in `_render_template__652100315_2182241460_0' + app/views/queries/execute.csv.erb:2:in `_render_template__652100315_2182241460_0' + app/controllers/queries_controller.rb:34:in `execute' + + Rendered /rails/actionpack-3.0.0.beta/lib/action_dispatch/middleware/templates/rescues/_trace.erb (1.0ms) + Rendered /rails/actionpack-3.0.0.beta/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (9.7ms) + Rendered /rails/actionpack-3.0.0.beta/lib/action_dispatch/middleware/templates/rescues/template_error.erb within /Users/willem/.rvm/gems/ruby-1.8.7-p248/gems/actionpack-3.0.0.beta/lib/action_dispatch/middleware/templates/rescues/layout.erb (20.4ms) + + EOLOG + + log_parser.should_receive(:handle_request).once + log_parser.should_receive(:warn).exactly(3).times + log_parser.parse_string(log) + end + end +end