log_subscriber_test.rb

require "abstract_unit"
require "active_support/log_subscriber/test_helper"
require "action_controller/log_subscriber"

module Another
  class LogSubscribersController < ActionController::Base
    wrap_parameters :person, :include => :name, :format => :json

    class SpecialException < Exception
    end

    rescue_from SpecialException do
      head :status => 406
    end

    before_action :redirector, only: :never_executed

    def never_executed
    end

    def show
      render :nothing => true
    end

    def redirector
      redirect_to "http://foo.bar/"
    end

    def filterable_redirector
      redirect_to "http://secret.foo.bar/"
    end

    def data_sender
      send_data "cool data", :filename => "file.txt"
    end

    def file_sender
      send_file File.expand_path("company.rb", FIXTURE_LOAD_PATH)
    end

    def with_fragment_cache
      render :inline => "<%= cache('foo'){ 'bar' } %>"
    end

    def with_fragment_cache_and_percent_in_key
      render :inline => "<%= cache('foo%bar'){ 'Contains % sign in key' } %>"
    end

    def with_fragment_cache_if_with_true_condition
      render :inline => "<%= cache_if(true, 'foo') { 'bar' } %>"
    end

    def with_fragment_cache_if_with_false_condition
      render :inline => "<%= cache_if(false, 'foo') { 'bar' } %>"
    end

    def with_fragment_cache_unless_with_false_condition
      render :inline => "<%= cache_unless(false, 'foo') { 'bar' } %>"
    end

    def with_fragment_cache_unless_with_true_condition
      render :inline => "<%= cache_unless(true, 'foo') { 'bar' } %>"
    end

    def with_exception
      raise Exception
    end

    def with_rescued_exception
      raise SpecialException
    end

    def with_action_not_found
      raise AbstractController::ActionNotFound
    end
  end
end

class ACLogSubscriberTest < ActionController::TestCase
  tests Another::LogSubscribersController
  include ActiveSupport::LogSubscriber::TestHelper

  def setup
    super

    @old_logger = ActionController::Base.logger

    @cache_path = File.expand_path('../temp/test_cache', File.dirname(__FILE__))
    @controller.cache_store = :file_store, @cache_path
    ActionController::LogSubscriber.attach_to :action_controller
  end

  def teardown
    super
    ActiveSupport::LogSubscriber.log_subscribers.clear
    FileUtils.rm_rf(@cache_path)
    ActionController::Base.logger = @old_logger
  end

  def set_logger(logger)
    ActionController::Base.logger = logger
  end

  def test_start_processing
    get :show
    wait
    assert_equal 2, logs.size
    assert_equal "Processing by Another::LogSubscribersController#show as HTML", logs.first
  end

  def test_halted_callback
    get :never_executed
    wait
    assert_equal 4, logs.size
    assert_equal "Filter chain halted as :redirector rendered or redirected", logs.third
  end

  def test_process_action
    get :show
    wait
    assert_equal 2, logs.size
    assert_match(/Completed/, logs.last)
    assert_match(/200 OK/, logs.last)
  end

  def test_process_action_without_parameters
    get :show
    wait
    assert_nil logs.detect {|l| l =~ /Parameters/ }
  end

  def test_process_action_with_parameters
    get :show, :id => '10'
    wait

    assert_equal 3, logs.size
    assert_equal 'Parameters: {"id"=>"10"}', logs[1]
  end

  def test_multiple_process_with_parameters
    get :show, :id => '10'
    get :show, :id => '20'

    wait

    assert_equal 6, logs.size
    assert_equal 'Parameters: {"id"=>"10"}', logs[1]
    assert_equal 'Parameters: {"id"=>"20"}', logs[4]
  end

  def test_process_action_with_wrapped_parameters
    @request.env['CONTENT_TYPE'] = 'application/json'
    post :show, :id => '10', :name => 'jose'
    wait

    assert_equal 3, logs.size
    assert_match '"person"=>{"name"=>"jose"}', logs[1]
  end

  def test_process_action_with_view_runtime
    get :show
    wait
    assert_match(/\(Views: [\d.]+ms\)/, logs[1])
  end

  def test_process_action_with_filter_parameters
    @request.env["action_dispatch.parameter_filter"] = [:lifo, :amount]

    get :show, :lifo => 'Pratik', :amount => '420', :step => '1'
    wait

    params = logs[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, logs.size
    assert_equal "Redirected to http://foo.bar/", logs[1]
  end

  def test_filter_redirect_url_by_string
    @request.env['action_dispatch.redirect_filter'] = ['secret']
    get :filterable_redirector
    wait

    assert_equal 3, logs.size
    assert_equal "Redirected to [FILTERED]", logs[1]
  end

  def test_filter_redirect_url_by_regexp
    @request.env['action_dispatch.redirect_filter'] = [/secret\.foo.+/]
    get :filterable_redirector
    wait

    assert_equal 3, logs.size
    assert_equal "Redirected to [FILTERED]", logs[1]
  end

  def test_send_data
    get :data_sender
    wait

    assert_equal 3, logs.size
    assert_match(/Sent data file\.txt/, logs[1])
  end

  def test_send_file
    get :file_sender
    wait

    assert_equal 3, logs.size
    assert_match(/Sent file/, logs[1])
    assert_match(/test\/fixtures\/company\.rb/, logs[1])
  end

  def test_with_fragment_cache
    @controller.config.perform_caching = true
    get :with_fragment_cache
    wait

    assert_equal 4, logs.size
    assert_match(/Read fragment views\/foo/, logs[1])
    assert_match(/Write fragment views\/foo/, logs[2])
  ensure
    @controller.config.perform_caching = true
  end

  def test_with_fragment_cache_if_with_true
    @controller.config.perform_caching = true
    get :with_fragment_cache_if_with_true_condition
    wait

    assert_equal 4, logs.size
    assert_match(/Read fragment views\/foo/, logs[1])
    assert_match(/Write fragment views\/foo/, logs[2])
  ensure
    @controller.config.perform_caching = true
  end

  def test_with_fragment_cache_if_with_false
    @controller.config.perform_caching = true
    get :with_fragment_cache_if_with_false_condition
    wait

    assert_equal 2, logs.size
    assert_no_match(/Read fragment views\/foo/, logs[1])
    assert_no_match(/Write fragment views\/foo/, logs[2])
  ensure
    @controller.config.perform_caching = true
  end

  def test_with_fragment_cache_unless_with_true
    @controller.config.perform_caching = true
    get :with_fragment_cache_unless_with_true_condition
    wait

    assert_equal 2, logs.size
    assert_no_match(/Read fragment views\/foo/, logs[1])
    assert_no_match(/Write fragment views\/foo/, logs[2])
  ensure
    @controller.config.perform_caching = true
  end

  def test_with_fragment_cache_unless_with_false
    @controller.config.perform_caching = true
    get :with_fragment_cache_unless_with_false_condition
    wait

    assert_equal 4, logs.size
    assert_match(/Read fragment views\/foo/, logs[1])
    assert_match(/Write fragment views\/foo/, logs[2])
  ensure
    @controller.config.perform_caching = true
  end

  def test_with_fragment_cache_and_percent_in_key
    @controller.config.perform_caching = true
    get :with_fragment_cache_and_percent_in_key
    wait

    assert_equal 4, logs.size
    assert_match(/Read fragment views\/foo/, logs[1])
    assert_match(/Write fragment views\/foo/, logs[2])
  ensure
    @controller.config.perform_caching = true
  end

  def test_process_action_with_exception_includes_http_status_code
    begin
      get :with_exception
      wait
    rescue Exception
    end
    assert_equal 2, logs.size
    assert_match(/Completed 500/, logs.last)
  end

  def test_process_action_with_rescued_exception_includes_http_status_code
    get :with_rescued_exception
    wait

    assert_equal 2, logs.size
    assert_match(/Completed 406/, logs.last)
  end

  def test_process_action_with_with_action_not_found_logs_404
    begin
      get :with_action_not_found
      wait
    rescue AbstractController::ActionNotFound
    end

    assert_equal 2, logs.size
    assert_match(/Completed 404/, logs.last)
  end

  def logs
    @logs ||= @logger.logged(:info)
  end
end