From da5978c22374b8a3b15a421ff4920e0940435253 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Wed, 13 Jan 2010 00:41:04 +0100 Subject: Add subscriber for ActionPack and move all logging inside it. --- actionpack/lib/action_controller.rb | 2 +- actionpack/lib/action_controller/base.rb | 5 +- actionpack/lib/action_controller/caching.rb | 11 --- .../metal/filter_parameter_logging.rb | 17 +--- .../lib/action_controller/metal/instrumentation.rb | 77 +++++++++++++++ actionpack/lib/action_controller/metal/logger.rb | 93 ------------------ .../lib/action_controller/metal/redirecting.rb | 2 - .../lib/action_controller/metal/streaming.rb | 4 - actionpack/lib/action_controller/railtie.rb | 11 +-- .../lib/action_controller/railties/subscriber.rb | 62 ++++++++++++ actionpack/lib/action_view/railtie.rb | 11 ++- actionpack/lib/action_view/railties/subscriber.rb | 24 +++++ actionpack/lib/action_view/template/text.rb | 2 +- actionpack/test/abstract_unit.rb | 26 ----- actionpack/test/controller/caching_test.rb | 14 --- actionpack/test/controller/filter_params_test.rb | 12 --- actionpack/test/controller/logging_test.rb | 81 ---------------- actionpack/test/controller/subscriber_test.rb | 108 +++++++++++++++++++++ actionpack/test/template/subscriber_test.rb | 74 ++++++++++++++ 19 files changed, 367 insertions(+), 269 deletions(-) create mode 100644 actionpack/lib/action_controller/metal/instrumentation.rb delete mode 100644 actionpack/lib/action_controller/metal/logger.rb create mode 100644 actionpack/lib/action_controller/railties/subscriber.rb create mode 100644 actionpack/lib/action_view/railties/subscriber.rb delete mode 100644 actionpack/test/controller/logging_test.rb create mode 100644 actionpack/test/controller/subscriber_test.rb create mode 100644 actionpack/test/template/subscriber_test.rb (limited to 'actionpack') diff --git a/actionpack/lib/action_controller.rb b/actionpack/lib/action_controller.rb index 8271f6f3e7..42582c4525 100644 --- a/actionpack/lib/action_controller.rb +++ b/actionpack/lib/action_controller.rb @@ -23,7 +23,7 @@ module ActionController autoload :Helpers autoload :HideActions autoload :HttpAuthentication - autoload :Logger + autoload :Instrumentation autoload :MimeResponds autoload :RackDelegation autoload :Redirecting diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb index 746ab3e6db..4f564a6377 100644 --- a/actionpack/lib/action_controller/base.rb +++ b/actionpack/lib/action_controller/base.rb @@ -15,7 +15,6 @@ module ActionController include ActionController::Renderers::All include ActionController::ConditionalGet include ActionController::RackDelegation - include ActionController::Logger include ActionController::Configuration # Legacy modules @@ -36,6 +35,10 @@ module ActionController include ActionController::FilterParameterLogging include ActionController::Translation + # Add instrumentations hooks at the bottom, to ensure they instrument + # all the methods properly. + include ActionController::Instrumentation + # TODO: Extract into its own module # This should be moved together with other normalizing behavior module ImplicitRender diff --git a/actionpack/lib/action_controller/caching.rb b/actionpack/lib/action_controller/caching.rb index 5c0d754ad6..d784138ebe 100644 --- a/actionpack/lib/action_controller/caching.rb +++ b/actionpack/lib/action_controller/caching.rb @@ -60,17 +60,6 @@ module ActionController #:nodoc: def cache_configured? perform_caching && cache_store end - - def log_event(name, before, after, instrumenter_id, payload) - if name.to_s =~ /action_controller\.((read|write|expire|exist)_(fragment|page)\??)/ - key_or_path = payload[:key] || payload[:path] - human_name = $1.humanize - duration = (after - before) * 1000 - logger.info("#{human_name} #{key_or_path.inspect} (%.1fms)" % duration) - else - super - end - end end def caching_allowed? diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb index 59e200396a..9e03f50759 100644 --- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb +++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb @@ -2,6 +2,8 @@ module ActionController module FilterParameterLogging extend ActiveSupport::Concern + INTERNAL_PARAMS = %w(controller action format _method only_path) + module ClassMethods # Replace sensitive parameter data from the request log. # Filters parameters that have any of the arguments as a substring. @@ -48,25 +50,12 @@ module ActionController filtered_params[key] = value end - filtered_params + filtered_params.except!(*INTERNAL_PARAMS) end protected :filter_parameters end - - protected - - # Overwrite log_process_action to include parameters information. - # If this method is invoked, it means logger is defined, so don't - # worry with such scenario here. - def log_process_action(controller) #:nodoc: - params = controller.send(:filter_parameters, controller.request.params) - logger.info " Parameters: #{params.inspect}" unless params.empty? - super - end end - INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] - protected def filter_parameters(params) diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb new file mode 100644 index 0000000000..91d454f0c3 --- /dev/null +++ b/actionpack/lib/action_controller/metal/instrumentation.rb @@ -0,0 +1,77 @@ +require 'abstract_controller/logger' + +module ActionController + # Adds instrumentation to several ends in ActionController::Base. It also provides + # some hooks related with process_action logging and view runtime. + module Instrumentation + extend ActiveSupport::Concern + + included do + include AbstractController::Logger + end + + attr_internal :view_runtime + + def process_action(action, *args) + ActiveSupport::Notifications.instrument("action_controller.process_action", + :controller => self, :action => action) do + super + end + end + + def render(*args, &block) + if logger + render_output = nil + + self.view_runtime = cleanup_view_runtime do + Benchmark.ms { render_output = super } + end + + render_output + else + super + end + end + + def send_file(path, options={}) + ActiveSupport::Notifications.instrument("action_controller.send_file", + options.merge(:path => path)) do + super + end + end + + def send_data(data, options = {}) + ActiveSupport::Notifications.instrument("action_controller.send_data", options) do + super + end + end + + def redirect_to(*args) + super + ActiveSupport::Notifications.instrument("action_controller.redirect_to", + :status => self.status, :location => self.location) + end + + # A hook which allows you to clean up any time taken into account in + # views wrongly, like database querying time. + # + # def cleanup_view_runtime + # super - time_taken_in_something_expensive + # end + # + # :api: plugin + def cleanup_view_runtime #:nodoc: + yield + end + + module ClassMethods + # A hook which allows other frameworks to log what happened during + # controller process action. + # :api: plugin + def log_process_action(controller) #:nodoc: + view_runtime = controller.send :view_runtime + logger.info(" View runtime: %.1fms" % view_runtime.to_f) if view_runtime + end + end + end +end \ No newline at end of file diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb deleted file mode 100644 index e995d6bcea..0000000000 --- a/actionpack/lib/action_controller/metal/logger.rb +++ /dev/null @@ -1,93 +0,0 @@ -require 'abstract_controller/logger' - -module ActionController - # Adds instrumentation to process_action and a log_event method - # responsible to log events from ActiveSupport::Notifications. This module handles - # :process_action and :render_template events but allows any other module to hook - # into log_event and provide its own logging facilities (as in ActionController::Caching). - module Logger - extend ActiveSupport::Concern - - included do - include AbstractController::Logger - end - - attr_internal :view_runtime - - def process_action(action) - ActiveSupport::Notifications.instrument("action_controller.process_action", - :controller => self, :action => action) do - super - end - end - - def render(*args, &block) - if logger - render_output = nil - - self.view_runtime = cleanup_view_runtime do - Benchmark.ms { render_output = super } - end - - render_output - else - super - end - end - - # If you want to remove any time taken into account in :view_runtime - # wrongly, you can do it here: - # - # def cleanup_view_runtime - # super - time_taken_in_something_expensive - # end - # - # :api: plugin - def cleanup_view_runtime #:nodoc: - yield - end - - module ClassMethods - # This is the hook invoked by ActiveSupport::Notifications.subscribe. - # If you need to log any event, overwrite the method and do it here. - def log_event(name, before, after, instrumenter_id, payload) #:nodoc: - if name == "action_controller.process_action" - duration = [(after - before) * 1000, 0.01].max - controller = payload[:controller] - request = controller.request - - logger.info "\nProcessed #{controller.class.name}##{payload[:action]} " \ - "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \ - "[#{request.method.to_s.upcase}]" - - log_process_action(controller) - - message = "Completed in %.0fms" % duration - message << " | #{controller.response.status}" - message << " [#{request.request_uri rescue "unknown"}]\n\n" - - logger.info(message) - elsif name == "action_view.render_template" - duration = (after - before) * 1000 - message = "Rendered #{from_rails_root(payload[:identifier])}" - message << " within #{from_rails_root(payload[:layout])}" if payload[:layout] - message << (" (%.1fms)" % duration) - logger.info(message) - end - end - - protected - - # A hook which allows logging what happened during controller process action. - # :api: plugin - def log_process_action(controller) #:nodoc: - view_runtime = controller.send :view_runtime - logger.info(" View runtime: %.1fms" % view_runtime.to_f) if view_runtime - end - - def from_rails_root(string) - defined?(Rails.root) ? string.sub("#{Rails.root}/app/views/", "") : string - end - end - end -end \ No newline at end of file diff --git a/actionpack/lib/action_controller/metal/redirecting.rb b/actionpack/lib/action_controller/metal/redirecting.rb index 7b277c0ae0..faf0589fd2 100644 --- a/actionpack/lib/action_controller/metal/redirecting.rb +++ b/actionpack/lib/action_controller/metal/redirecting.rb @@ -57,8 +57,6 @@ module ActionController self.status = _extract_redirect_to_status(options, response_status) self.location = _compute_redirect_to_location(options) self.response_body = "You are being redirected." - - logger.info("Redirected to #{location}") if logger && logger.info? end private diff --git a/actionpack/lib/action_controller/metal/streaming.rb b/actionpack/lib/action_controller/metal/streaming.rb index 288b5d7c99..8f03b8bb17 100644 --- a/actionpack/lib/action_controller/metal/streaming.rb +++ b/actionpack/lib/action_controller/metal/streaming.rb @@ -88,13 +88,11 @@ module ActionController #:nodoc: @performed_render = false if options[:x_sendfile] - logger.info "Sending #{X_SENDFILE_HEADER} header #{path}" if logger head options[:status], X_SENDFILE_HEADER => path else if options[:stream] # TODO : Make render :text => proc {} work with the new base render :status => options[:status], :text => Proc.new { |response, output| - logger.info "Streaming file #{path}" unless logger.nil? len = options[:buffer_size] || 4096 File.open(path, 'rb') do |file| while buf = file.read(len) @@ -103,7 +101,6 @@ module ActionController #:nodoc: end } else - logger.info "Sending file #{path}" unless logger.nil? File.open(path, 'rb') { |file| render :status => options[:status], :text => file.read } end end @@ -141,7 +138,6 @@ module ActionController #:nodoc: # data to the browser, then use render :text => proc { ... } # instead. See ActionController::Base#render for more information. def send_data(data, options = {}) #:doc: - logger.info "Sending data #{options[:filename]}" if logger send_file_headers! options.merge(:length => data.bytesize) render :status => options[:status], :text => data end diff --git a/actionpack/lib/action_controller/railtie.rb b/actionpack/lib/action_controller/railtie.rb index 42257f9400..d4886ecefd 100644 --- a/actionpack/lib/action_controller/railtie.rb +++ b/actionpack/lib/action_controller/railtie.rb @@ -5,6 +5,9 @@ module ActionController class Railtie < Rails::Railtie plugin_name :action_controller + require "action_controller/railties/subscriber" + subscriber ActionController::Railties::Subscriber.new + initializer "action_controller.set_configs" do |app| app.config.action_controller.each do |k,v| ActionController::Base.send "#{k}=", v @@ -86,13 +89,5 @@ module ActionController end end - initializer "action_controller.notifications" do |app| - require 'active_support/notifications' - - ActiveSupport::Notifications.subscribe do |*args| - ActionController::Base.log_event(*args) if ActionController::Base.logger - end - end - end end diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb new file mode 100644 index 0000000000..d9d77304ee --- /dev/null +++ b/actionpack/lib/action_controller/railties/subscriber.rb @@ -0,0 +1,62 @@ +module ActionController + module Railties + class Subscriber < Rails::Subscriber + def process_action(event) + controller = event.payload[:controller] + request = controller.request + + info "\nProcessed #{controller.class.name}##{event.payload[:action]} " \ + "to #{request.formats} (for #{request.remote_ip} at #{event.time.to_s(:db)}) " \ + "[#{request.method.to_s.upcase}]" + + params = controller.send(:filter_parameters, request.params) + info " Parameters: #{params.inspect}" unless params.empty? + + ActionController::Base.log_process_action(controller) + + message = "Completed in %.0fms" % event.duration + message << " | #{controller.response.status}" + message << " [#{request.request_uri rescue "unknown"}]\n\n" + + info(message) + end + + def send_file(event) + message = if event.payload[:x_sendfile] + header = ActionController::Streaming::X_SENDFILE_HEADER + "Sending #{header} header %s" + elsif event.payload[:stream] + "Streaming file %s" + else + "Sending file %s" + end + + message << " (%.1fms)" + info(message % [event.payload[:path], event.duration]) + end + + def redirect_to(event) + info "Redirected to #{event.payload[:location]} with status #{event.payload[:status]}" + end + + def send_data(event) + info("Sending data %s (%.1fms)" % [event.payload[:filename], event.duration]) + end + + %w(write_fragment read_fragment exist_fragment? + expire_fragment expire_page write_page).each do |method| + class_eval <<-METHOD, __FILE__, __LINE__ + 1 + def #{method}(event) + key_or_path = event.payload[:key] || event.payload[:path] + human_name = #{method.to_s.humanize.inspect} + info("\#{human_name} \#{key_or_path.inspect} (%.1fms)" % event.duration) + end + METHOD + end + + def logger + ActionController::Base.logger + end + end + end +end \ No newline at end of file diff --git a/actionpack/lib/action_view/railtie.rb b/actionpack/lib/action_view/railtie.rb index a90e0636b9..e368aab825 100644 --- a/actionpack/lib/action_view/railtie.rb +++ b/actionpack/lib/action_view/railtie.rb @@ -1,2 +1,11 @@ require "action_view" -require "rails" \ No newline at end of file +require "rails" + +module ActionView + class Railtie < Rails::Railtie + plugin_name :action_view + + require "action_view/railties/subscriber" + subscriber ActionView::Railties::Subscriber.new + end +end \ No newline at end of file diff --git a/actionpack/lib/action_view/railties/subscriber.rb b/actionpack/lib/action_view/railties/subscriber.rb new file mode 100644 index 0000000000..803f19379c --- /dev/null +++ b/actionpack/lib/action_view/railties/subscriber.rb @@ -0,0 +1,24 @@ +module ActionView + module Railties + class Subscriber < Rails::Subscriber + def render_template(event) + message = "Rendered #{from_rails_root(event.payload[:identifier])}" + message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] + message << (" (%.1fms)" % event.duration) + info(message) + end + alias :render_partial :render_template + alias :render_collection :render_template + + def logger + ActionController::Base.logger + end + + protected + + def from_rails_root(string) + string.sub("#{Rails.root}/", "").sub(/^app\/views\//, "") + end + end + end +end \ No newline at end of file diff --git a/actionpack/lib/action_view/template/text.rb b/actionpack/lib/action_view/template/text.rb index 67e086d8bd..2abb352d4e 100644 --- a/actionpack/lib/action_view/template/text.rb +++ b/actionpack/lib/action_view/template/text.rb @@ -13,7 +13,7 @@ module ActionView #:nodoc: end def identifier - self + 'text template' end def inspect diff --git a/actionpack/test/abstract_unit.rb b/actionpack/test/abstract_unit.rb index 3f7a5c89b9..3e631d45df 100644 --- a/actionpack/test/abstract_unit.rb +++ b/actionpack/test/abstract_unit.rb @@ -48,14 +48,6 @@ ORIGINAL_LOCALES = I18n.available_locales.map {|locale| locale.to_s }.sort FIXTURE_LOAD_PATH = File.join(File.dirname(__FILE__), 'fixtures') FIXTURES = Pathname.new(FIXTURE_LOAD_PATH) -# Turn on notifications -require 'active_support/notifications' -Thread.abort_on_exception = true - -ActiveSupport::Notifications.subscribe do |*args| - ActionController::Base.log_event(*args) if ActionController::Base.logger -end - module SetupOnce extend ActiveSupport::Concern @@ -93,24 +85,6 @@ class ActiveSupport::TestCase end end -class MockLogger - attr_accessor :level - - def initialize - @level = Logger::DEBUG - @logged = [] - end - - def method_missing(method, *args, &blk) - @logged << args.first - @logged << blk.call if block_given? - end - - def logged - @logged.compact.map { |l| l.to_s.strip } - end -end - class ActionController::IntegrationTest < ActiveSupport::TestCase def self.build_app(routes = nil) ActionDispatch::MiddlewareStack.new { |middleware| diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb index 5a8dc0c358..8a13d1e5f1 100644 --- a/actionpack/test/controller/caching_test.rb +++ b/actionpack/test/controller/caching_test.rb @@ -629,20 +629,6 @@ class FragmentCachingTest < ActionController::TestCase assert_equal 'generated till now -> fragment content', buffer end - def test_fragment_for_logging - # Wait pending notifications to be published - ActiveSupport::Notifications.notifier.wait - @controller.logger = MockLogger.new - - fragment_computed = false - @controller.fragment_for('buffer', 'expensive') { fragment_computed = true } - ActiveSupport::Notifications.notifier.wait - - assert fragment_computed - assert_match /Exist fragment\? "views\/expensive"/, @controller.logger.logged[0] - assert_match /Write fragment "views\/expensive"/, @controller.logger.logged[1] - end - end class FunctionalCachingController < ActionController::Base diff --git a/actionpack/test/controller/filter_params_test.rb b/actionpack/test/controller/filter_params_test.rb index 420ebeacf4..d0635669c2 100644 --- a/actionpack/test/controller/filter_params_test.rb +++ b/actionpack/test/controller/filter_params_test.rb @@ -66,18 +66,6 @@ class FilterParamTest < ActionController::TestCase assert_raise(NoMethodError) { @controller.filter_parameters([{'password' => '[FILTERED]'}]) } end - def test_filter_parameters_inside_logs - FilterParamController.filter_parameter_logging(:lifo, :amount) - - get :payment, :lifo => 'Pratik', :amount => '420', :step => '1' - ActiveSupport::Notifications.notifier.wait - - filtered_params_logs = logs.detect {|l| l =~ /\AParameters/ } - assert filtered_params_logs.index('"amount"=>"[FILTERED]"') - assert filtered_params_logs.index('"lifo"=>"[FILTERED]"') - assert filtered_params_logs.index('"step"=>"1"') - end - private def set_logger diff --git a/actionpack/test/controller/logging_test.rb b/actionpack/test/controller/logging_test.rb deleted file mode 100644 index 594cf17312..0000000000 --- a/actionpack/test/controller/logging_test.rb +++ /dev/null @@ -1,81 +0,0 @@ -require 'abstract_unit' - -module Another - class LoggingController < ActionController::Base - layout "layouts/standard" - - def show - render :nothing => true - end - - def with_layout - render :template => "test/hello_world", :layout => true - end - end -end - -class LoggingTest < ActionController::TestCase - tests Another::LoggingController - - def setup - super - wait # Wait pending notifications to be published - set_logger - end - - def get(*args) - super - wait - end - - def wait - ActiveSupport::Notifications.notifier.wait - end - - def test_logging_without_parameters - get :show - assert_equal 4, logs.size - assert_nil logs.detect {|l| l =~ /Parameters/ } - end - - def test_logging_with_parameters - get :show, :id => '10' - assert_equal 5, logs.size - - params = logs.detect {|l| l =~ /Parameters/ } - assert_equal 'Parameters: {"id"=>"10"}', params - end - - def test_log_controller_with_namespace_and_action - get :show - assert_match /Processed\sAnother::LoggingController#show/, logs[1] - end - - def test_log_view_runtime - get :show - assert_match /View runtime/, logs[2] - end - - def test_log_completed_status_and_request_uri - get :show - last = logs.last - assert_match /Completed/, last - assert_match /200/, last - assert_match /another\/logging\/show/, last - end - - def test_logger_prints_layout_and_template_rendering_info - get :with_layout - logged = logs.find {|l| l =~ /render/i } - assert_match /Rendered (.*)test\/hello_world.erb within (.*)layouts\/standard.html.erb/, logged - end - - private - def set_logger - @controller.logger = MockLogger.new - end - - def logs - @logs ||= @controller.logger.logged - end -end diff --git a/actionpack/test/controller/subscriber_test.rb b/actionpack/test/controller/subscriber_test.rb new file mode 100644 index 0000000000..e2c6150c5e --- /dev/null +++ b/actionpack/test/controller/subscriber_test.rb @@ -0,0 +1,108 @@ +require "abstract_unit" +require "rails/subscriber/test_helper" +require "action_controller/railties/subscriber" + +module Another + class SubscribersController < ActionController::Base + def show + render :nothing => true + end + + def redirector + redirect_to "http://foo.bar/" + end + end +end + +module ActionControllerSubscriberTest + Rails::Subscriber.add(:action_controller, ActionController::Railties::Subscriber.new) + + def self.included(base) + base.tests Another::SubscribersController + end + + def wait + sleep(0.01) + super + end + + def setup + @old_logger = ActionController::Base.logger + super + end + + def teardown + super + ActionController::Base.logger = @old_logger + end + + def set_logger(logger) + ActionController::Base.logger = logger + end + + def test_process_action + get :show + wait + assert_equal 3, @logger.logged(:info).size + assert_match /Processed\sAnother::SubscribersController#show/, @logger.logged(:info)[0] + end + + def test_process_action_without_parameters + get :show + wait + assert_nil @logger.logged(:info).detect {|l| l =~ /Parameters/ } + end + + def test_process_action_with_parameters + get :show, :id => '10' + wait + + assert_equal 4, @logger.logged(:info).size + assert_equal 'Parameters: {"id"=>"10"}', @logger.logged(:info)[1] + end + + def test_process_action_with_view_runtime + get :show + wait + assert_match /View runtime/, @logger.logged(:info)[1] + end + + def test_process_action_with_status_and_request_uri + get :show + wait + last = @logger.logged(:info).last + assert_match /Completed/, last + assert_match /200/, last + assert_match /another\/subscribers\/show/, last + end + + def test_process_action_with_filter_parameters + Another::SubscribersController.filter_parameter_logging(:lifo, :amount) + + get :show, :lifo => 'Pratik', :amount => '420', :step => '1' + wait + + params = @logger.logged(:info)[1] + assert_match /"amount"=>"\[FILTERED\]"/, params + assert_match /"lifo"=>"\[FILTERED\]"/, params + assert_match /"step"=>"1"/, params + end + + def test_redirect_to + get :redirector + wait + + assert_equal 3, @logger.logged(:info).size + assert_equal "Redirected to http://foo.bar/ with status 302", @logger.logged(:info)[0] + end + + class SyncSubscriberTest < ActionController::TestCase + include Rails::Subscriber::SyncTestHelper + include ActionControllerSubscriberTest + end + + class AsyncSubscriberTest < ActionController::TestCase + include Rails::Subscriber::AsyncTestHelper + include ActionControllerSubscriberTest + end +end diff --git a/actionpack/test/template/subscriber_test.rb b/actionpack/test/template/subscriber_test.rb new file mode 100644 index 0000000000..a73ff2e932 --- /dev/null +++ b/actionpack/test/template/subscriber_test.rb @@ -0,0 +1,74 @@ +require "abstract_unit" +require "rails/subscriber/test_helper" +require "action_view/railties/subscriber" +require "controller/fake_models" + +module ActionViewSubscriberTest + Rails::Subscriber.add(:action_view, ActionView::Railties::Subscriber.new) + + def setup + @old_logger = ActionController::Base.logger + @view = ActionView::Base.new(ActionController::Base.view_paths, {}) + Rails.stubs(:root).returns(File.expand_path(FIXTURE_LOAD_PATH)) + super + end + + def teardown + super + ActionController::Base.logger = @old_logger + end + + def set_logger(logger) + ActionController::Base.logger = logger + end + + def test_render_file_template + @view.render(:file => "test/hello_world.erb") + wait + + assert_equal 1, @logger.logged(:info).size + assert_match /Rendered test\/hello_world\.erb/, @logger.logged(:info).last + end + + def test_render_text_template + @view.render(:text => "OMG") + wait + + assert_equal 1, @logger.logged(:info).size + assert_match /Rendered text template/, @logger.logged(:info).last + end + + def test_render_inline_template + @view.render(:inline => "<%= 'OMG' %>") + wait + + assert_equal 1, @logger.logged(:info).size + assert_match /Rendered inline template/, @logger.logged(:info).last + end + + def test_render_partial_template + @view.render(:partial => "test/customer") + wait + + assert_equal 1, @logger.logged(:info).size + assert_match /Rendered test\/_customer.erb/, @logger.logged(:info).last + end + + def test_render_collection_template + @view.render(:partial => "test/customer", :collection => [ Customer.new("david"), Customer.new("mary") ]) + wait + + assert_equal 1, @logger.logged(:info).size + assert_match /Rendered test\/_customer.erb/, @logger.logged(:info).last + end + + class SyncSubscriberTest < ActiveSupport::TestCase + include Rails::Subscriber::SyncTestHelper + include ActionViewSubscriberTest + end + + class AsyncSubscriberTest < ActiveSupport::TestCase + include Rails::Subscriber::AsyncTestHelper + include ActionViewSubscriberTest + end +end \ No newline at end of file -- cgit v1.2.3