1 # -*- encoding: binary -*-
2 $stderr.sync = $stdout.sync = true
11 # used to test subclasses
12 class FooString < String
15 class TestClogger < Test::Unit::TestCase
16 include Clogger::Format
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',
32 Clogger.new(lambda { |env| [ 0, {}, [] ] })
36 assert_raise(ArgumentError) { Clogger.new }
40 cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => $stderr)
41 assert_kind_of(Integer, cl.fileno)
42 assert_equal $stderr.fileno, cl.fileno
45 def test_init_stringio
46 cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => StringIO.new)
50 def test_write_stringio
51 start = DateTime.now - 1
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 }
59 r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 302 -\n\z}
61 %r{\[([^\]]+)\]} =~ str
63 assert_nothing_raised {
64 tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
67 assert tmp <= DateTime.now
70 def test_clen_stringio
71 start = DateTime.now - 1
73 app = lambda { |env| [ 301, {'Content-Length' => '5'}, ['abcde'] ] }
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) }
82 r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 301 5\n\z}
84 %r{\[([^\]]+)\]} =~ str
86 assert_nothing_raised {
87 tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
90 assert tmp <= DateTime.now
93 def test_compile_ambiguous
94 cl = Clogger.new(nil, :logger => $stderr)
98 '$remote_addr $$$$pid' \
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" ],
108 assert_equal expect, ary
111 def test_compile_auto_newline
112 cl = Clogger.new(nil, :logger => $stderr)
114 cl.instance_eval { ary = compile_format('$remote_addr $request') }
116 [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
117 [ Clogger::OP_LITERAL, " " ],
118 [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
119 [ Clogger::OP_LITERAL, "\n" ],
121 assert_equal expect, ary
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
133 'HTTP_HOST' => 'example.com:12345',
134 'HTTP_COOKIE' => cookie,
136 req = @req.merge(req)
137 cl.call(req).last.each { |part| part }
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
145 cl = Clogger.new(nil, :logger => $stderr)
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}' \
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" ],
179 assert_equal expect, ary
183 current = Thread.current.to_s
185 app = lambda { |env| [ 302, {}, [] ] }
186 cl = Clogger.new(app,
188 :format => "-$e{Thread.current}-\n")
189 status, headers, body = cl.call(@req)
190 assert_equal "-#{current}-\n", str.string
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
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
210 status, headers, body = cl.call(@req)
211 assert_equal "home\n", str.string
217 start = DateTime.now - 1
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)
223 body.each { |s| tmp << s }
224 assert_equal %w(a b c), tmp
226 assert_match %r[" 200 3 \d+\.\d{4}\n\z], str
228 %r{\[(\d+/\w+/\d+ \d+:\d+:\d+)\]} =~ str
230 assert_nothing_raised { tmp = DateTime.strptime($1, "%d/%b/%Y %H:%M:%S") }
232 assert tmp <= DateTime.now
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
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
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
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
267 def test_request_length
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
276 def test_response_length_0
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
286 start = DateTime.now - 1
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)
292 body.each { |s| tmp << s }
293 assert_equal %w(a b c), tmp
295 assert_match %r[" 200 3 "-" "echo and socat \\o/"\n\z], str
297 %r{\[(\d+/\w+/\d+:\d+:\d+:\d+ .+)\]} =~ str
299 assert_nothing_raised {
300 tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
303 assert tmp <= DateTime.now
306 def test_rack_errors_fallback
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
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?
327 app = lambda { |env| [ 200, {'Content-Length'=>'5'}, [] ] }
328 cl = Clogger.new(app,
330 :format => '$http_user_agent "$request"')
332 'HTTP_USER_AGENT' => '"asdf"',
333 'QUERY_STRING' => 'sdf=bar"',
334 'PATH_INFO' => '/"<>"',
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
341 # rack allows repeated headers with "\n":
342 # { 'Set-Cookie' => "a\nb" } =>
345 def test_escape_header_newlines
347 app = lambda { |env| [302, { 'Set-Cookie' => "a\nb" }, [] ] }
348 cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
350 assert_equal "a\\x0Ab\n", str.string
353 def test_request_uri_fallback
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
361 def test_request_uri_set
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
372 req = Rack::Request.new(env).cookies
375 cl = Clogger.new(app,
376 :format => '$cookie_foo $cookie_quux',
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
383 def test_bogus_app_response
385 app = lambda { |env| 302 }
386 cl = Clogger.new(app, :logger => str)
387 assert_raise(TypeError) { cl.call(@req) }
389 e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
390 assert_match %r{#{e}$}m, str
393 def test_broken_header_response
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) }
400 def test_subclass_hash
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 {} }
409 def test_subclassed_string_req
412 @req.each { |key,value|
413 req[FooString.new(key)] = value.kind_of?(String) ?
414 FooString.new(value) : value
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 {} }
422 def test_subclassed_string_in_body
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 } }
430 assert_equal body.size.to_s << "\n", str.string
432 assert r.object_id != body.object_id
435 def test_http_09_request
437 app = lambda { |env| [302, [ %w(a) ], []] }
438 cl = Clogger.new(app, :logger => str, :format => '$request')
440 req.delete 'HTTP_VERSION'
442 assert_equal "GET /hello?goodbye=true\n", str.string
445 def test_request_method_only
447 app = lambda { |env| [302, [ %w(a) ], []] }
448 cl = Clogger.new(app, :logger => str, :format => '$request_method')
450 assert_equal "GET\n", str.string
453 def test_content_length_null
455 app = lambda { |env| [302, [ %w(a) ], []] }
456 cl = Clogger.new(app, :logger => str, :format => '$content_length')
458 assert_equal "-\n", str.string
461 def test_content_length_set
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
469 def test_http_content_type_fallback
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
477 def test_clogger_synced
479 logger = Struct.new(:sync, :io).new(false, io)
484 app = lambda { |env| [302, [ %w(a) ], []] }
485 cl = Clogger.new(app, :logger => logger)
489 def test_clogger_unsyncable
491 assert ! logger.respond_to?('sync=')
492 app = lambda { |env| [302, [ %w(a) ], []] }
493 assert_nothing_raised { Clogger.new(app, :logger => logger) }
496 def test_clogger_no_ORS
498 app = lambda { |env| [302, [ %w(a) ], []] }
499 cl = Clogger.new(app, :logger => s, :format => "$request", :ORS => "")
501 assert_equal "GET /hello?goodbye=true HTTP/1.0", s
504 def test_clogger_weird_ORS
506 app = lambda { |env| [302, [ %w(a) ], []] }
507 cl = Clogger.new(app, :logger => s, :format => "<$request", :ORS => ">")
509 assert_equal "<GET /hello?goodbye=true HTTP/1.0>", s
512 def test_clogger_body_not_closeable
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
520 def test_clogger_response_frozen
521 response = [ 200, { "AAAA" => "AAAA"}.freeze, [].freeze ].freeze
523 app = Rack::Builder.new do
524 use Clogger, :logger => s, :format => "$request_time $http_host"
525 run lambda { |env| response }
527 assert_nothing_raised do
529 resp = app.call(@req)
530 assert ! resp.frozen?
531 resp.last.each { |x| }
536 def test_clogger_body_close_return_value
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
548 def test_clogger_auto_reentrant_true
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)
558 def test_clogger_auto_reentrant_false
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?
568 def test_clogger_auto_reentrant_forced_true
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)
579 def test_clogger_auto_reentrant_forced_false
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?
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"
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
600 1000000.times { clogger.dup }
601 File.read(LINUX_PROC_PID_STATUS) =~ match_rss
603 diff = after - before
604 assert(diff < 10000, "memory grew more than 10M: #{diff}")
606 end if RUBY_PLATFORM =~ /linux/ && test(?r, LINUX_PROC_PID_STATUS)