aboutsummaryrefslogtreecommitdiffstats
path: root/actionpack/test/controller/log_subscriber_test.rb
blob: cbebc6b59c236095229ce086b6834d303a69e312 (plain) (blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
# frozen_string_literal: true

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 406
    end

    before_action :redirector, only: :never_executed

    def never_executed
    end

    def show
      head :ok
    end

    def redirector
      redirect_to "http://foo.bar/", allow_other_host: true
    end

    def filterable_redirector
      redirect_to "http://secret.foo.bar/", allow_other_host: true
    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

    def append_info_to_payload(payload)
      super
      payload[:test_key] = "test_value"
      @last_payload = payload
    end

    attr_reader :last_payload
  end
end

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

  def setup
    super
    ActionController::Base.enable_fragment_cache_logging = true

    @old_logger = ActionController::Base.logger

    @cache_path = Dir.mktmpdir(%w[tmp cache])
    @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
    ActionController::Base.enable_fragment_cache_logging = true
  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, params: { id: "10" }
    wait

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

  def test_multiple_process_with_parameters
    get :show, params: { id: "10" }
    get :show, params: { 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, params: { 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(/Completed 200 OK in \d+ms/, logs[1])
  end

  def test_append_info_to_payload_is_called_even_with_exception
    begin
      get :with_exception
      wait
    rescue Exception
    end

    assert_equal "test_value", @controller.last_payload[:test_key]
  end

  def test_process_action_headers
    get :show
    wait
    assert_equal "Rails Testing", @controller.last_payload[:headers]["User-Agent"]
  end

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

    get :show, params: {
      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_when_log_disabled
    @controller.config.perform_caching = true
    ActionController::Base.enable_fragment_cache_logging = false
    get :with_fragment_cache
    wait

    assert_equal 2, logs.size
    assert_equal "Processing by Another::LogSubscribersController#with_fragment_cache as HTML", logs[0]
    assert_match(/Completed 200 OK in \d+ms/, logs[1])
  ensure
    @controller.config.perform_caching = true
    ActionController::Base.enable_fragment_cache_logging = 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