JezK
Edit File: analytics_logging_extensions_spec.rb
require File.expand_path(File.dirname(__FILE__) + '/../../spec_helper') require 'socket' require 'fileutils' require 'phusion_passenger/analytics_logger' require 'phusion_passenger/utils/tmpdir' module PhusionPassenger shared_examples_for "analytics logging extensions for Rails" do before :each do @logging_agent_password = "1234" @agent_pid, @socket_filename, @socket_address = spawn_logging_agent(Utils.passenger_tmpdir, @logging_agent_password) @options = { "analytics" => true, "logging_agent_address" => @socket_address, "logging_agent_username" => "logging", "logging_agent_password_base64" => base64("1234"), "node_name" => "localhost" } end after :each do @connection.close if @connection && @connection.closed? Process.kill('KILL', @agent_pid) Process.waitpid(@agent_pid) end def send_request_to_app(app, env) if app.server_sockets[:main][1] == "unix" @connection = UNIXSocket.new(app.server_sockets[:main][0]) else addr, port = app.server_sockets[:main][0].split(/:/) @connection = TCPSocket.new(addr, port.to_i) end channel = MessageChannel.new(@connection) data = "" env = { "REQUEST_METHOD" => "GET", "SCRIPT_NAME" => "", "PATH_INFO" => "/", "QUERY_STRING" => "", "SERVER_NAME" => "localhost", "SERVER_PORT" => "80", "PASSENGER_TXN_ID" => "1234-abcd", "PASSENGER_GROUP_NAME" => "foobar" }.merge(env) env["REQUEST_URI"] ||= env["PATH_INFO"] env.each_pair do |key, value| data << key << "\0" data << value << "\0" end channel.write_scalar(data) return @connection.read end def read_log(name_suffix) filename = Dir["#{Utils.passenger_tmpdir}/1/*/*/#{name_suffix}"].first if filename return File.read(filename) else return "" end end def base64(data) return [data].pack('m').gsub("\n", "") end it "doesn't install analytics logging extensions if analytics logging is turned off" do @options.delete("analytics") app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index File.open("out.txt", "w") do |f| f.write(request.env["PASSENGER_ANALYTICS_WEB_LOG"].class.to_s) end render :nothing => true end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do filename = "#{app.app_root}/out.txt" File.exist?(filename) && File.read(filename) == "NilClass" end end it "logs the controller and action name" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index render :nothing => true end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("Controller action: FooController#index\n") end end it "logs uncaught exceptions in controller actions" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/crash_controller.rb", %Q{ class CrashController < ActionController::Base def index raise "something went wrong" end end }) end send_request_to_app(app, "PATH_INFO" => "/crash") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("exceptions/**/log.txt") log.include?("Request transaction ID: 1234-abcd\n") && log.include?("Message: " + base64("something went wrong")) && log.include?("Class: RuntimeError") && log.include?("Backtrace: ") && log.include?("Controller action: CrashController#index") end end it "logs ActionController benchmarks" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index # The '::' prefix works around a Dependencies # bug in Rails 1.2 ::ActionController::Base.benchmark("hello") do end render :nothing => true end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?('BEGIN: BENCHMARK: hello') && log.include?('END: BENCHMARK: hello') end end it "logs ActionView benchmarks" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base end }) FileUtils.mkdir_p("#{stub.app_root}/app/views/foo") File.write("#{stub.app_root}/app/views/foo/index.rhtml", %Q{ <% benchmark("hello") do %> <% end %> }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?('BEGIN: BENCHMARK: hello') && log.include?('END: BENCHMARK: hello') end end it "logs successful SQL queries" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/config/database.yml", "production:\n" + " adapter: sqlite3\n" + " database: db.sqlite3\n") File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index db = ActiveRecord::Base.connection db.execute("CREATE TABLE foobar (id INT)") db.execute("INSERT INTO foobar VALUES (1)") render :nothing => true end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") extra_info_regex = Regexp.escape(base64("SQL\nCREATE TABLE foobar (id INT)")) eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log =~ /BEGIN: DB BENCHMARK: .* \(.*\) #{extra_info_regex}$/ && log =~ /END: DB BENCHMARK: .* \(.*\)$/ end end it "logs failed SQL queries" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/config/database.yml", "production:\n" + " adapter: sqlite3\n" + " database: db.sqlite3\n") File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index db = ActiveRecord::Base.connection db.execute("INVALID QUERY") render :nothing => true end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") extra_info_regex = Regexp.escape(base64("SQL\nINVALID QUERY")) if rails_version >= '3.0' pending do eventually(5) do log = read_log("requests/**/log.txt") log =~ /BEGIN: DB BENCHMARK: .* \(.*\) #{extra_info_regex}$/ && log =~ /FAIL: DB BENCHMARK: .* \(.*\)$/ end end else eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log =~ /BEGIN: DB BENCHMARK: .* \(.*\) #{extra_info_regex}$/ && log =~ /FAIL: DB BENCHMARK: .* \(.*\)$/ end end end it "logs controller processing time of successful actions" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index render :nothing => true end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("BEGIN: framework request processing") && log.include?("END: framework request processing") end end it "logs controller processing time of failed actions" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index raise "crash" end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("BEGIN: framework request processing") && log.include?("FAIL: framework request processing") end end it "logs view rendering time of successful actions" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index end end }) FileUtils.mkdir_p("#{stub.app_root}/app/views/foo") File.write("#{stub.app_root}/app/views/foo/index.rhtml", %Q{ hello world }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("BEGIN: view rendering") && log.include?("END: view rendering") && log =~ /View rendering time: \d+$/ end end it "logs view rendering time of failed actions" do app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index end end }) FileUtils.mkdir_p("#{stub.app_root}/app/views/foo") File.write("#{stub.app_root}/app/views/foo/index.rhtml", %Q{ <% raise "crash!" %> }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("BEGIN: view rendering") && log.include?("FAIL: view rendering") end end it "logs cache hits" do if rails_version >= '2.1' app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index Rails.cache.write("key1", "foo") Rails.cache.write("key2", "foo") Rails.cache.write("key3", "foo") Rails.cache.read("key1") Rails.cache.fetch("key2") Rails.cache.fetch("key3") { "bar" } render :text => 'ok' end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("Cache hit: key1") && log.include?("Cache hit: key2") && log.include?("Cache hit: key3") end end end it "logs cache misses" do if rails_version >= '2.1' app = spawn_some_application(@options) do |stub| File.write("#{stub.app_root}/app/controllers/foo_controller.rb", %Q{ class FooController < ActionController::Base def index Rails.cache.read("key1") Rails.cache.fetch("key2") Rails.cache.fetch("key3") { "bar" } render :text => 'ok' end end }) end send_request_to_app(app, "PATH_INFO" => "/foo") eventually(5) do flush_logging_agent(@logging_agent_password, @socket_address) log = read_log("requests/**/log.txt") log.include?("Cache miss: key1") && log.include?("Cache miss: key2") && log =~ /Cache miss \(\d+\): key3/ end end end end end # module PhusionPassenger