ext: fix memory leak when reentrant/multithreaded
[clogger.git] / test / test_clogger.rb
blob4dab3fc6201646e41edb3f9bbc8eaaaad845e897
1 # -*- encoding: binary -*-
2 $stderr.sync = $stdout.sync = true
3 require "test/unit"
4 require "date"
5 require "stringio"
7 require "rack"
9 require "clogger"
11 # used to test subclasses
12 class FooString < String
13 end
15 class TestClogger < Test::Unit::TestCase
16   include Clogger::Format
18   def setup
19     @req = {
20       "REQUEST_METHOD" => "GET",
21       "HTTP_VERSION" => "HTTP/1.0",
22       "HTTP_USER_AGENT" => 'echo and socat \o/',
23       "PATH_INFO" => "/hello",
24       "QUERY_STRING" => "goodbye=true",
25       "rack.errors" => $stderr,
26       "rack.input" => File.open('/dev/null', 'rb'),
27       "REMOTE_ADDR" => 'home',
28     }
29   end
31   def test_init_basic
32     Clogger.new(lambda { |env| [ 0, {}, [] ] })
33   end
35   def test_init_noargs
36     assert_raise(ArgumentError) { Clogger.new }
37   end
39   def test_init_stderr
40     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => $stderr)
41     assert_kind_of(Integer, cl.fileno)
42     assert_equal $stderr.fileno, cl.fileno
43   end
45   def test_init_stringio
46     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => StringIO.new)
47     assert_nil cl.fileno
48   end
50   def test_write_stringio
51     start = DateTime.now - 1
52     str = StringIO.new
53     cl = Clogger.new(lambda { |env| [ "302 Found", {}, [] ] }, :logger => str)
54     status, headers, body = cl.call(@req)
55     assert_equal("302 Found", status)
56     assert_equal({}, headers)
57     body.each { |part| assert false }
58     str = str.string
59     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 302 -\n\z}
60     assert_match r, str
61     %r{\[([^\]]+)\]} =~ str
62     tmp = nil
63     assert_nothing_raised {
64       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
65     }
66     assert tmp >= start
67     assert tmp <= DateTime.now
68   end
70   def test_clen_stringio
71     start = DateTime.now - 1
72     str = StringIO.new
73     app = lambda { |env| [ 301, {'Content-Length' => '5'}, ['abcde'] ] }
74     format = Common.dup
75     assert format.gsub!(/response_length/, 'sent_http_content_length')
76     cl = Clogger.new(app, :logger => str, :format => format)
77     status, headers, body = cl.call(@req)
78     assert_equal(301, status)
79     assert_equal({'Content-Length' => '5'}, headers)
80     body.each { |part| assert_equal('abcde', part) }
81     str = str.string
82     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 301 5\n\z}
83     assert_match r, str
84     %r{\[([^\]]+)\]} =~ str
85     tmp = nil
86     assert_nothing_raised {
87       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
88     }
89     assert tmp >= start
90     assert tmp <= DateTime.now
91   end
93   def test_compile_ambiguous
94     cl = Clogger.new(nil, :logger => $stderr)
95     ary = nil
96     cl.instance_eval {
97       ary = compile_format(
98         '$remote_addr $$$$pid' \
99         "\n")
100     }
101     expect = [
102       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
103       [ Clogger::OP_LITERAL, " " ],
104       [ Clogger::OP_LITERAL, "$$$" ],
105       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:pid] ],
106       [ Clogger::OP_LITERAL, "\n" ],
107       ]
108     assert_equal expect, ary
109   end
111   def test_compile_auto_newline
112     cl = Clogger.new(nil, :logger => $stderr)
113     ary = nil
114     cl.instance_eval { ary = compile_format('$remote_addr $request') }
115     expect = [
116       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
117       [ Clogger::OP_LITERAL, " " ],
118       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
119       [ Clogger::OP_LITERAL, "\n" ],
120       ]
121     assert_equal expect, ary
122   end
124   def test_big_log
125     str = StringIO.new
126     fmt = '$remote_addr $pid $remote_user [$time_local] ' \
127           '"$request" $status $body_bytes_sent "$http_referer" ' \
128          '"$http_user_agent" "$http_cookie" $request_time $http_host'
129     app = lambda { |env| [ 302, {}, [] ] }
130     cl = Clogger.new(app, :logger => str, :format => fmt)
131     cookie = "foo=bar#{'f' * 256}".freeze
132     req = {
133       'HTTP_HOST' => 'example.com:12345',
134       'HTTP_COOKIE' => cookie,
135     }
136     req = @req.merge(req)
137     cl.call(req).last.each { |part| part }
138     str = str.string
139     assert(str.size > 128)
140     assert_match %r["echo and socat \\o/" "#{cookie}" \d+\.\d{3}], str
141     assert_match %r["#{cookie}" \d+\.\d{3} example\.com:12345\n\z], str
142   end
144   def test_compile
145     cl = Clogger.new(nil, :logger => $stderr)
146     ary = nil
147     cl.instance_eval {
148       ary = compile_format(
149         '$remote_addr - $remote_user [$time_local] ' \
150         '"$request" $status $body_bytes_sent "$http_referer" ' \
151         '"$http_user_agent" "$http_cookie" $request_time ' \
152         '$env{rack.url_scheme}' \
153         "\n")
154     }
155     expect = [
156       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
157       [ Clogger::OP_LITERAL, " - " ],
158       [ Clogger::OP_REQUEST, "REMOTE_USER" ],
159       [ Clogger::OP_LITERAL, " [" ],
160       [ Clogger::OP_TIME_LOCAL, '%d/%b/%Y:%H:%M:%S %z' ],
161       [ Clogger::OP_LITERAL, "] \"" ],
162       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
163       [ Clogger::OP_LITERAL, "\" "],
164       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:status] ],
165       [ Clogger::OP_LITERAL, " "],
166       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:body_bytes_sent] ],
167       [ Clogger::OP_LITERAL, " \"" ],
168       [ Clogger::OP_REQUEST, "HTTP_REFERER" ],
169       [ Clogger::OP_LITERAL, "\" \"" ],
170       [ Clogger::OP_REQUEST, "HTTP_USER_AGENT" ],
171       [ Clogger::OP_LITERAL, "\" \"" ],
172       [ Clogger::OP_REQUEST, "HTTP_COOKIE" ],
173       [ Clogger::OP_LITERAL, "\" " ],
174       [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000 ],
175       [ Clogger::OP_LITERAL, " " ],
176       [ Clogger::OP_REQUEST, "rack.url_scheme" ],
177       [ Clogger::OP_LITERAL, "\n" ],
178     ]
179     assert_equal expect, ary
180   end
182   def test_eval
183     current = Thread.current.to_s
184     str = StringIO.new
185     app = lambda { |env| [ 302, {}, [] ] }
186     cl = Clogger.new(app,
187                     :logger => str,
188                     :format => "-$e{Thread.current}-\n")
189     status, headers, body = cl.call(@req)
190     assert_equal "-#{current}-\n", str.string
191   end
193   def test_pid
194     str = StringIO.new
195     app = lambda { |env| [ 302, {}, [] ] }
196     cl = Clogger.new(app, :logger => str, :format => "[$pid]\n")
197     status, headers, body = cl.call(@req)
198     assert_equal "[#$$]\n", str.string
199   end
201   def test_rack_xff
202     str = StringIO.new
203     app = lambda { |env| [ 302, {}, [] ] }
204     cl = Clogger.new(app, :logger => str, :format => "$ip")
205     req = @req.merge("HTTP_X_FORWARDED_FOR" => '192.168.1.1')
206     status, headers, body = cl.call(req)
207     assert_equal "192.168.1.1\n", str.string
208     str.rewind
209     str.truncate(0)
210     status, headers, body = cl.call(@req)
211     assert_equal "home\n", str.string
212     str.rewind
213     str.truncate(0)
214   end
216   def test_rack_1_0
217     start = DateTime.now - 1
218     str = StringIO.new
219     app = lambda { |env| [ 200, {'Content-Length'=>'0'}, %w(a b c)] }
220     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
221     status, headers, body = cl.call(@req)
222     tmp = []
223     body.each { |s| tmp << s }
224     assert_equal %w(a b c), tmp
225     str = str.string
226     assert_match %r[" 200 3 \d+\.\d{4}\n\z], str
227     tmp = nil
228     %r{\[(\d+/\w+/\d+ \d+:\d+:\d+)\]} =~ str
229     assert $1
230     assert_nothing_raised { tmp = DateTime.strptime($1, "%d/%b/%Y %H:%M:%S") }
231     assert tmp >= start
232     assert tmp <= DateTime.now
233   end
235   def test_msec
236     str = StringIO.new
237     app = lambda { |env| [ 200, {}, [] ] }
238     cl = Clogger.new(app, :logger => str, :format => '$msec')
239     status, header, bodies = cl.call(@req)
240     assert_match %r(\A\d+\.\d{3}\n\z), str.string
241   end
243   def test_usec
244     str = StringIO.new
245     app = lambda { |env| [ 200, {}, [] ] }
246     cl = Clogger.new(app, :logger => str, :format => '$usec')
247     status, header, bodies = cl.call(@req)
248     assert_match %r(\A\d+\.\d{6}\n\z), str.string
249   end
251   def test_time_0
252     str = StringIO.new
253     app = lambda { |env| [ 200, {}, [] ] }
254     cl = Clogger.new(app, :logger => str, :format => '$time{0}')
255     status, header, bodies = cl.call(@req)
256     assert_match %r(\A\d+\n\z), str.string
257   end
259   def test_time_1
260     str = StringIO.new
261     app = lambda { |env| [ 200, {}, [] ] }
262     cl = Clogger.new(app, :logger => str, :format => '$time{1}')
263     status, header, bodies = cl.call(@req)
264     assert_match %r(\A\d+\.\d\n\z), str.string
265   end
267   def test_request_length
268     str = StringIO.new
269     input = StringIO.new('.....')
270     app = lambda { |env| [ 200, {}, [] ] }
271     cl = Clogger.new(app, :logger => str, :format => '$request_length')
272     status, header, bodies = cl.call(@req.merge('rack.input' => input))
273     assert_equal "5\n", str.string
274   end
276   def test_response_length_0
277     str = StringIO.new
278     app = lambda { |env| [ 200, {}, [] ] }
279     cl = Clogger.new(app, :logger => str, :format => '$response_length')
280     status, header, bodies = cl.call(@req)
281     bodies.each { |part| part }
282     assert_equal "-\n", str.string
283   end
285   def test_combined
286     start = DateTime.now - 1
287     str = StringIO.new
288     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
289     cl = Clogger.new(app, :logger => str, :format => Combined)
290     status, headers, body = cl.call(@req)
291     tmp = []
292     body.each { |s| tmp << s }
293     assert_equal %w(a b c), tmp
294     str = str.string
295     assert_match %r[" 200 3 "-" "echo and socat \\o/"\n\z], str
296     tmp = nil
297     %r{\[(\d+/\w+/\d+:\d+:\d+:\d+ .+)\]} =~ str
298     assert $1
299     assert_nothing_raised {
300       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
301     }
302     assert tmp >= start
303     assert tmp <= DateTime.now
304   end
306   def test_rack_errors_fallback
307     err = StringIO.new
308     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
309     cl = Clogger.new(app, :format => '$pid')
310     req = @req.merge('rack.errors' => err)
311     status, headers, body = cl.call(req)
312     assert_equal "#$$\n", err.string
313   end
315   def test_body_close
316     s_body = StringIO.new(%w(a b c).join("\n"))
317     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, s_body] }
318     cl = Clogger.new(app, :logger => [], :format => '$pid')
319     status, headers, body = cl.call(@req)
320     assert ! s_body.closed?
321     assert_nothing_raised { body.close }
322     assert s_body.closed?
323   end
325   def test_escape
326     str = StringIO.new
327     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, [] ] }
328     cl = Clogger.new(app,
329       :logger => str,
330       :format => '$http_user_agent "$request"')
331     bad = {
332       'HTTP_USER_AGENT' => '"asdf"',
333       'QUERY_STRING' => 'sdf=bar"',
334       'PATH_INFO' => '/"<>"',
335     }
336     status, headers, body = cl.call(@req.merge(bad))
337     expect = '\x22asdf\x22 "GET /\x22<>\x22?sdf=bar\x22 HTTP/1.0"' << "\n"
338     assert_equal expect, str.string
339   end
341   # rack allows repeated headers with "\n":
342   # { 'Set-Cookie' => "a\nb" } =>
343   #   Set-Cookie: a
344   #   Set-Cookie: b
345   def test_escape_header_newlines
346     str = StringIO.new
347     app = lambda { |env| [302, { 'Set-Cookie' => "a\nb" }, [] ] }
348     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
349     cl.call(@req)
350     assert_equal "a\\x0Ab\n", str.string
351   end
353   def test_request_uri_fallback
354     str = StringIO.new
355     app = lambda { |env| [ 200, {}, [] ] }
356     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
357     status, headers, body = cl.call(@req)
358     assert_equal "/hello?goodbye=true\n", str.string
359   end
361   def test_request_uri_set
362     str = StringIO.new
363     app = lambda { |env| [ 200, {}, [] ] }
364     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
365     status, headers, body = cl.call(@req.merge("REQUEST_URI" => '/zzz'))
366     assert_equal "/zzz\n", str.string
367   end
369   def test_cookies
370     str = StringIO.new
371     app = lambda { |env|
372       req = Rack::Request.new(env).cookies
373       [ 302, {}, [] ]
374     }
375     cl = Clogger.new(app,
376         :format => '$cookie_foo $cookie_quux',
377         :logger => str)
378     req = @req.merge('HTTP_COOKIE' => "foo=bar;quux=h&m")
379     status, headers, body = cl.call(req)
380     assert_equal "bar h&m\n", str.string
381   end
383   def test_bogus_app_response
384     str = StringIO.new
385     app = lambda { |env| 302 }
386     cl = Clogger.new(app, :logger => str)
387     assert_raise(TypeError) { cl.call(@req) }
388     str = str.string
389     e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
390     assert_match %r{#{e}$}m, str
391   end
393   def test_broken_header_response
394     str = StringIO.new
395     app = lambda { |env| [302, [ %w(a) ], []] }
396     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
397     assert_nothing_raised { cl.call(@req) }
398   end
400   def test_subclass_hash
401     str = StringIO.new
402     req = Rack::Utils::HeaderHash.new(@req)
403     app = lambda { |env| [302, [ %w(a) ], []] }
404     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
405     assert_nothing_raised { cl.call(req).last.each {} }
406     assert str.size > 0
407   end
409   def test_subclassed_string_req
410     str = StringIO.new
411     req = {}
412     @req.each { |key,value|
413       req[FooString.new(key)] = value.kind_of?(String) ?
414                                 FooString.new(value) : value
415     }
416     app = lambda { |env| [302, [ %w(a) ], []] }
417     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
418     assert_nothing_raised { cl.call(req).last.each {} }
419     assert str.size > 0
420   end
422   def test_subclassed_string_in_body
423     str = StringIO.new
424     body = "hello"
425     r = nil
426     app = lambda { |env| [302, [ %w(a) ], [FooString.new(body)]] }
427     cl = Clogger.new(app, :logger => str, :format => '$body_bytes_sent')
428     assert_nothing_raised { cl.call(@req).last.each { |x| r = x } }
429     assert str.size > 0
430     assert_equal body.size.to_s << "\n", str.string
431     assert_equal r, body
432     assert r.object_id != body.object_id
433   end
435   def test_http_09_request
436     str = StringIO.new
437     app = lambda { |env| [302, [ %w(a) ], []] }
438     cl = Clogger.new(app, :logger => str, :format => '$request')
439     req = @req.dup
440     req.delete 'HTTP_VERSION'
441     cl.call(req)
442     assert_equal "GET /hello?goodbye=true\n", str.string
443   end
445   def test_request_method_only
446     str = StringIO.new
447     app = lambda { |env| [302, [ %w(a) ], []] }
448     cl = Clogger.new(app, :logger => str, :format => '$request_method')
449     cl.call(@req)
450     assert_equal "GET\n", str.string
451   end
453   def test_content_length_null
454     str = StringIO.new
455     app = lambda { |env| [302, [ %w(a) ], []] }
456     cl = Clogger.new(app, :logger => str, :format => '$content_length')
457     cl.call(@req)
458     assert_equal "-\n", str.string
459   end
461   def test_content_length_set
462     str = StringIO.new
463     app = lambda { |env| [302, [ %w(a) ], []] }
464     cl = Clogger.new(app, :logger => str, :format => '$content_length')
465     cl.call(@req.merge('CONTENT_LENGTH' => '5'))
466     assert_equal "5\n", str.string
467   end
469   def test_http_content_type_fallback
470     str = StringIO.new
471     app = lambda { |env| [302, [ %w(a) ], []] }
472     cl = Clogger.new(app, :logger => str, :format => '$http_content_type')
473     cl.call(@req.merge('CONTENT_TYPE' => 'text/plain'))
474     assert_equal "text/plain\n", str.string
475   end
477   def test_clogger_synced
478     io = StringIO.new
479     logger = Struct.new(:sync, :io).new(false, io)
480     assert ! logger.sync
481     def logger.<<(str)
482       io << str
483     end
484     app = lambda { |env| [302, [ %w(a) ], []] }
485     cl = Clogger.new(app, :logger => logger)
486     assert logger.sync
487   end
489   def test_clogger_unsyncable
490     logger = ''
491     assert ! logger.respond_to?('sync=')
492     app = lambda { |env| [302, [ %w(a) ], []] }
493     assert_nothing_raised { Clogger.new(app, :logger => logger) }
494   end
496   def test_clogger_no_ORS
497     s = ''
498     app = lambda { |env| [302, [ %w(a) ], []] }
499     cl = Clogger.new(app, :logger => s, :format => "$request", :ORS => "")
500     cl.call(@req)
501     assert_equal "GET /hello?goodbye=true HTTP/1.0", s
502   end
504   def test_clogger_weird_ORS
505     s = ''
506     app = lambda { |env| [302, [ %w(a) ], []] }
507     cl = Clogger.new(app, :logger => s, :format => "<$request", :ORS => ">")
508     cl.call(@req)
509     assert_equal "<GET /hello?goodbye=true HTTP/1.0>", s
510   end
512   def test_clogger_body_not_closeable
513     s = ''
514     app = lambda { |env| [302, [ %w(a) ], []] }
515     cl = Clogger.new(app, :logger => s)
516     status, headers, body = cl.call(@req)
517     assert_nil body.close
518   end
520   def test_clogger_response_frozen
521     response = [ 200, { "AAAA" => "AAAA"}.freeze, [].freeze ].freeze
522     s = StringIO.new("")
523     app = Rack::Builder.new do
524       use Clogger, :logger => s, :format => "$request_time $http_host"
525       run lambda { |env| response }
526     end
527     assert_nothing_raised do
528       3.times do
529         resp = app.call(@req)
530         assert ! resp.frozen?
531         resp.last.each { |x| }
532       end
533     end
534   end
536   def test_clogger_body_close_return_value
537     s = ''
538     body = []
539     def body.close
540       :foo
541     end
542     app = lambda { |env| [302, [ %w(a) ], body ] }
543     cl = Clogger.new(app, :logger => s)
544     status, headers, body = cl.call(@req)
545     assert_equal :foo, body.close
546   end
548   def test_clogger_auto_reentrant_true
549     s = ''
550     body = []
551     app = lambda { |env| [302, [ %w(a) ], body ] }
552     cl = Clogger.new(app, :logger => s, :format => "$request_time")
553     @req['rack.multithread'] = true
554     status, headers, body = cl.call(@req)
555     assert cl.reentrant?
556   end
558   def test_clogger_auto_reentrant_false
559     s = ''
560     body = []
561     app = lambda { |env| [302, [ %w(a) ], body ] }
562     cl = Clogger.new(app, :logger => s, :format => "$request_time")
563     @req['rack.multithread'] = false
564     status, headers, body = cl.call(@req)
565     assert ! cl.reentrant?
566   end
568   def test_clogger_auto_reentrant_forced_true
569     s = ''
570     body = []
571     app = lambda { |env| [302, [ %w(a) ], body ] }
572     o = { :logger => s, :format => "$request_time", :reentrant => true }
573     cl = Clogger.new(app, o)
574     @req['rack.multithread'] = false
575     status, headers, body = cl.call(@req)
576     assert cl.reentrant?
577   end
579   def test_clogger_auto_reentrant_forced_false
580     s = ''
581     body = []
582     app = lambda { |env| [302, [ %w(a) ], body ] }
583     o = { :logger => s, :format => "$request_time", :reentrant => false }
584     cl = Clogger.new(app, o)
585     @req['rack.multithread'] = true
586     status, headers, body = cl.call(@req)
587     assert ! cl.reentrant?
588   end
590   # so we don't  care about the portability of this test
591   # if it doesn't leak on Linux, it won't leak anywhere else
592   # unless your C compiler or platform is otherwise broken
593   LINUX_PROC_PID_STATUS = "/proc/self/status"
594   def test_memory_leak
595     app = lambda { |env| [ 0, {}, [] ] }
596     clogger = Clogger.new(app, :logger => $stderr)
597     match_rss = /^VmRSS:\s+(\d+)/
598     if File.read(LINUX_PROC_PID_STATUS) =~ match_rss
599       before = $1.to_i
600       1000000.times { clogger.dup }
601       File.read(LINUX_PROC_PID_STATUS) =~ match_rss
602       after = $1.to_i
603       diff = after - before
604       assert(diff < 10000, "memory grew more than 10M: #{diff}")
605     end
606   end if RUBY_PLATFORM =~ /linux/ && test(?r, LINUX_PROC_PID_STATUS)