test/test_clogger.rb

   1 # -*- encoding: binary -*-
   2 $stderr.sync = $stdout.sync = true
   3 require "test/unit"
   4 require "time"
   5 require "date"
   6 require "stringio"
   7 require "tempfile"
   8
   9 require "rack"
  10
  11 require "clogger"
  12
  13 # used to test subclasses
  14 class FooString < String
  15 end
  16
  17 class TestClogger < Test::Unit::TestCase
  18   include Clogger::Format
  19
  20   def setup
  21     @tz = ENV["TZ"]
  22     @nginx_fmt = "%d/%b/%Y:%H:%M:%S %z"
  23     @req = {
  24       "REQUEST_METHOD" => "GET",
  25       "HTTP_VERSION" => "HTTP/1.0",
  26       "HTTP_USER_AGENT" => 'echo and socat \o/',
  27       "PATH_INFO" => "/hello",
  28       "QUERY_STRING" => "goodbye=true",
  29       "rack.errors" => $stderr,
  30       "rack.input" => File.open('/dev/null', 'rb'),
  31       "REMOTE_ADDR" => 'home',
  32     }
  33   end
  34
  35   def teardown
  36     ENV["TZ"] = @tz
  37   end
  38
  39   def test_init_basic
  40     Clogger.new(lambda { |env| [ 0, {}, [] ] })
  41   end
  42
  43   def test_init_noargs
  44     assert_raise(ArgumentError) { Clogger.new }
  45   end
  46
  47   def test_clogger_sym_format
  48     app = lambda { |env| [ 0, {}, [] ] }
  49     tmp = Clogger.new app, :format => :Rack_1_0, :logger => $stderr
  50   end
  51
  52   def test_init_stderr
  53     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => $stderr)
  54     assert_kind_of(Integer, cl.fileno)
  55     assert_equal $stderr.fileno, cl.fileno
  56   end
  57
  58   def test_init_stringio
  59     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => StringIO.new)
  60     assert_nil cl.fileno
  61   end
  62
  63   def test_write_stringio
  64     start = DateTime.now - 1
  65     str = StringIO.new
  66     cl = Clogger.new(lambda { |env| [ "302 Found", {}, [] ] }, :logger => str)
  67     status, headers, body = cl.call(@req)
  68     assert_equal("302 Found", status)
  69     assert_equal({}, headers)
  70     body.each { |part| assert false }
  71     body.close
  72     str = str.string
  73     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 302 -\n\z}
  74     assert_match r, str
  75     %r{\[([^\]]+)\]} =~ str
  76     tmp = nil
  77     assert_nothing_raised {
  78       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
  79     }
  80     assert tmp >= start
  81     assert tmp <= DateTime.now
  82   end
  83
  84   def test_clen_stringio
  85     start = DateTime.now - 1
  86     str = StringIO.new
  87     app = lambda { |env| [ 301, {'Content-Length' => '5'}, ['abcde'] ] }
  88     format = Common.dup
  89     assert format.gsub!(/response_length/, 'sent_http_content_length')
  90     cl = Clogger.new(app, :logger => str, :format => format)
  91     status, headers, body = cl.call(@req)
  92     assert_equal(301, status)
  93     assert_equal({'Content-Length' => '5'}, headers)
  94     body.each { |part| assert_equal('abcde', part) }
  95     str = str.string
  96     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 301 5\n\z}
  97     assert_match r, str
  98     %r{\[([^\]]+)\]} =~ str
  99     tmp = nil
 100     assert_nothing_raised {
 101       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
 102     }
 103     assert tmp >= start
 104     assert tmp <= DateTime.now
 105   end
 106
 107   def test_compile_ambiguous
 108     cl = Clogger.new(nil, :logger => $stderr)
 109     ary = nil
 110     cl.instance_eval {
 111       ary = compile_format(
 112         '$remote_addr $$$$pid' \
 113         "\n")
 114     }
 115     expect = [
 116       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 117       [ Clogger::OP_LITERAL, " " ],
 118       [ Clogger::OP_LITERAL, "$$$" ],
 119       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:pid] ],
 120       [ Clogger::OP_LITERAL, "\n" ],
 121       ]
 122     assert_equal expect, ary
 123   end
 124
 125   def test_compile_auto_newline
 126     cl = Clogger.new(nil, :logger => $stderr)
 127     ary = nil
 128     cl.instance_eval { ary = compile_format('$remote_addr $request') }
 129     expect = [
 130       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 131       [ Clogger::OP_LITERAL, " " ],
 132       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
 133       [ Clogger::OP_LITERAL, "\n" ],
 134       ]
 135     assert_equal expect, ary
 136   end
 137
 138   def test_big_log
 139     str = StringIO.new
 140     fmt = '$remote_addr $pid $remote_user [$time_local] ' \
 141           '"$request" $status $body_bytes_sent "$http_referer" ' \
 142          '"$http_user_agent" "$http_cookie" $request_time $http_host'
 143     app = lambda { |env| [ 302, {}, [] ] }
 144     cl = Clogger.new(app, :logger => str, :format => fmt)
 145     cookie = "foo=bar#{'f' * 256}".freeze
 146     req = {
 147       'HTTP_HOST' => 'example.com:12345',
 148       'HTTP_COOKIE' => cookie,
 149     }
 150     req = @req.merge(req)
 151     body = cl.call(req).last
 152     body.each { |part| part }
 153     body.close
 154     str = str.string
 155     assert(str.size > 128)
 156     assert_match %r["echo and socat \\o/" "#{cookie}" \d+\.\d{3}], str
 157     assert_match %r["#{cookie}" \d+\.\d{3} example\.com:12345\n\z], str
 158   end
 159
 160   def test_compile
 161     cl = Clogger.new(nil, :logger => $stderr)
 162     ary = nil
 163     cl.instance_eval {
 164       ary = compile_format(
 165         '$remote_addr - $remote_user [$time_local] ' \
 166         '"$request" $status $body_bytes_sent "$http_referer" ' \
 167         '"$http_user_agent" "$http_cookie" $request_time ' \
 168         '$env{rack.url_scheme}' \
 169         "\n")
 170     }
 171     expect = [
 172       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 173       [ Clogger::OP_LITERAL, " - " ],
 174       [ Clogger::OP_REQUEST, "REMOTE_USER" ],
 175       [ Clogger::OP_LITERAL, " [" ],
 176       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:time_local] ],
 177       [ Clogger::OP_LITERAL, "] \"" ],
 178       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
 179       [ Clogger::OP_LITERAL, "\" "],
 180       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:status] ],
 181       [ Clogger::OP_LITERAL, " "],
 182       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:body_bytes_sent] ],
 183       [ Clogger::OP_LITERAL, " \"" ],
 184       [ Clogger::OP_REQUEST, "HTTP_REFERER" ],
 185       [ Clogger::OP_LITERAL, "\" \"" ],
 186       [ Clogger::OP_REQUEST, "HTTP_USER_AGENT" ],
 187       [ Clogger::OP_LITERAL, "\" \"" ],
 188       [ Clogger::OP_REQUEST, "HTTP_COOKIE" ],
 189       [ Clogger::OP_LITERAL, "\" " ],
 190       [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000 ],
 191       [ Clogger::OP_LITERAL, " " ],
 192       [ Clogger::OP_REQUEST, "rack.url_scheme" ],
 193       [ Clogger::OP_LITERAL, "\n" ],
 194     ]
 195     assert_equal expect, ary
 196   end
 197
 198   def test_eval
 199     current = Thread.current.to_s
 200     str = StringIO.new
 201     app = lambda { |env| [ 302, {}, [] ] }
 202     cl = Clogger.new(app,
 203                     :logger => str,
 204                     :format => "-$e{Thread.current}-\n")
 205     status, headers, body = cl.call(@req)
 206     assert_equal "-#{current}-\n", str.string
 207   end
 208
 209   def test_pid
 210     str = StringIO.new
 211     app = lambda { |env| [ 302, {}, [] ] }
 212     cl = Clogger.new(app, :logger => str, :format => "[$pid]\n")
 213     status, headers, body = cl.call(@req)
 214     assert_equal "[#$$]\n", str.string
 215   end
 216
 217   def test_rack_xff
 218     str = StringIO.new
 219     app = lambda { |env| [ 302, {}, [] ] }
 220     cl = Clogger.new(app, :logger => str, :format => "$ip")
 221     req = @req.merge("HTTP_X_FORWARDED_FOR" => '192.168.1.1')
 222     status, headers, body = cl.call(req)
 223     assert_equal "192.168.1.1\n", str.string
 224     str.rewind
 225     str.truncate(0)
 226     status, headers, body = cl.call(@req)
 227     assert_equal "home\n", str.string
 228     str.rewind
 229     str.truncate(0)
 230   end
 231
 232   def test_rack_1_0
 233     start = DateTime.now - 1
 234     str = StringIO.new
 235     app = lambda { |env| [ 200, {'Content-Length'=>'0'}, %w(a b c)] }
 236     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 237     status, headers, body = cl.call(@req)
 238     tmp = []
 239     body.each { |s| tmp << s }
 240     body.close
 241     assert_equal %w(a b c), tmp
 242     str = str.string
 243     assert_match %r[" 200 3 \d+\.\d{4}\n\z], str
 244     tmp = nil
 245     %r{\[(\d+/\w+/\d+ \d+:\d+:\d+)\]} =~ str
 246     assert $1
 247     assert_nothing_raised { tmp = DateTime.strptime($1, "%d/%b/%Y %H:%M:%S") }
 248     assert tmp >= start
 249     assert tmp <= DateTime.now
 250   end
 251
 252   def test_msec
 253     str = StringIO.new
 254     app = lambda { |env| [ 200, {}, [] ] }
 255     cl = Clogger.new(app, :logger => str, :format => '$msec')
 256     a = Time.now.to_f - 0.001
 257     status, header, bodies = cl.call(@req)
 258     assert_match %r(\A\d+\.\d{3}\n\z), str.string
 259     b = Time.now.to_f + 0.001
 260     logged = str.string.to_f
 261     assert logged >= a, "#{logged} >= #{a}"
 262     assert logged <= b, "#{logged} <= #{b}"
 263   end
 264
 265   def test_usec
 266     str = StringIO.new
 267     app = lambda { |env| [ 200, {}, [] ] }
 268     cl = Clogger.new(app, :logger => str, :format => '$usec')
 269     a = Time.now.to_f - 0.000001
 270     status, header, bodies = cl.call(@req)
 271     assert_match %r(\A\d+\.\d{6}\n\z), str.string
 272     b = Time.now.to_f + 0.000001
 273     logged = str.string.to_f
 274     assert logged >= a, "#{logged} >= #{a}"
 275     assert logged <= b, "#{logged} <= #{b}"
 276   end
 277
 278   def test_time_0
 279     str = StringIO.new
 280     app = lambda { |env| [ 200, {}, [] ] }
 281     cl = Clogger.new(app, :logger => str, :format => '$time{0}')
 282     a = Time.now.to_f - 1
 283     status, header, bodies = cl.call(@req)
 284     assert_match %r(\A\d+\n\z), str.string
 285     b = Time.now.to_f + 1
 286     logged = str.string.to_f
 287     assert logged >= a, "#{logged} >= #{a}"
 288     assert logged <= b, "#{logged} <= #{b}"
 289   end
 290
 291   def test_time_1
 292     str = StringIO.new
 293     app = lambda { |env| [ 200, {}, [] ] }
 294     cl = Clogger.new(app, :logger => str, :format => '$time{1}')
 295     a = Time.now.to_f - 0.5
 296     status, header, bodies = cl.call(@req)
 297     assert_match %r(\A\d+\.\d\n\z), str.string
 298     b = Time.now.to_f + 0.5
 299     logged = str.string.to_f
 300     assert logged >= a, "#{logged} >= #{a}"
 301     assert logged <= b, "#{logged} <= #{b}"
 302   end
 303
 304   def test_request_length
 305     str = StringIO.new
 306     input = StringIO.new('.....')
 307     app = lambda { |env| [ 200, {}, [] ] }
 308     cl = Clogger.new(app, :logger => str, :format => '$request_length')
 309     status, header, bodies = cl.call(@req.merge('rack.input' => input))
 310     assert_equal "5\n", str.string
 311   end
 312
 313   def test_response_length_0
 314     str = StringIO.new
 315     app = lambda { |env| [ 200, {}, [] ] }
 316     cl = Clogger.new(app, :logger => str, :format => '$response_length')
 317     status, header, bodies = cl.call(@req)
 318     bodies.each { |part| part }
 319     bodies.close
 320     assert_equal "-\n", str.string
 321   end
 322
 323   def test_combined
 324     start = DateTime.now - 1
 325     str = StringIO.new
 326     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
 327     cl = Clogger.new(app, :logger => str, :format => Combined)
 328     status, headers, body = cl.call(@req)
 329     tmp = []
 330     body.each { |s| tmp << s }
 331     body.close
 332     assert_equal %w(a b c), tmp
 333     str = str.string
 334     assert_match %r[" 200 3 "-" "echo and socat \\o/"\n\z], str
 335     tmp = nil
 336     %r{\[(\d+/\w+/\d+:\d+:\d+:\d+ .+)\]} =~ str
 337     assert $1
 338     assert_nothing_raised {
 339       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
 340     }
 341     assert tmp >= start
 342     assert tmp <= DateTime.now
 343   end
 344
 345   def test_rack_errors_fallback
 346     err = StringIO.new
 347     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
 348     cl = Clogger.new(app, :format => '$pid')
 349     req = @req.merge('rack.errors' => err)
 350     status, headers, body = cl.call(req)
 351     assert_equal "#$$\n", err.string
 352   end
 353
 354   def test_body_close
 355     s_body = StringIO.new(%w(a b c).join("\n"))
 356     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, s_body] }
 357     cl = Clogger.new(app, :logger => [], :format => '$pid')
 358     status, headers, body = cl.call(@req)
 359     assert ! s_body.closed?
 360     assert_nothing_raised { body.close }
 361     assert s_body.closed?
 362   end
 363
 364   def test_escape
 365     str = StringIO.new
 366     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, [] ] }
 367     cl = Clogger.new(app,
 368       :logger => str,
 369       :format => '$http_user_agent "$request"')
 370     bad = {
 371       'HTTP_USER_AGENT' => '"asdf"',
 372       'QUERY_STRING' => 'sdf=bar"',
 373       'PATH_INFO' => '/"<>"',
 374     }
 375     status, headers, body = cl.call(@req.merge(bad))
 376     expect = '\x22asdf\x22 "GET /\x22<>\x22?sdf=bar\x22 HTTP/1.0"' << "\n"
 377     assert_equal expect, str.string
 378   end
 379
 380   # rack allows repeated headers with "\n":
 381   # { 'Set-Cookie' => "a\nb" } =>
 382   #   Set-Cookie: a
 383   #   Set-Cookie: b
 384   def test_escape_header_newlines
 385     str = StringIO.new
 386     app = lambda { |env| [302, { 'Set-Cookie' => "a\nb" }, [] ] }
 387     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 388     cl.call(@req)
 389     assert_equal "a\\x0Ab\n", str.string
 390   end
 391
 392   def test_request_uri_fallback
 393     str = StringIO.new
 394     app = lambda { |env| [ 200, {}, [] ] }
 395     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 396     status, headers, body = cl.call(@req)
 397     assert_equal "/hello?goodbye=true\n", str.string
 398   end
 399
 400   def test_request_uri_set
 401     str = StringIO.new
 402     app = lambda { |env| [ 200, {}, [] ] }
 403     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 404     status, headers, body = cl.call(@req.merge("REQUEST_URI" => '/zzz'))
 405     assert_equal "/zzz\n", str.string
 406   end
 407
 408   def test_cookies
 409     str = StringIO.new
 410     app = lambda { |env|
 411       req = Rack::Request.new(env).cookies
 412       [ 302, {}, [] ]
 413     }
 414     cl = Clogger.new(app,
 415         :format => '$cookie_foo $cookie_quux',
 416         :logger => str)
 417     req = @req.merge('HTTP_COOKIE' => "foo=bar;quux=h&m")
 418     status, headers, body = cl.call(req)
 419     assert_equal "bar h&m\n", str.string
 420   end
 421
 422   def test_bogus_app_response
 423     str = StringIO.new
 424     app = lambda { |env| 302 }
 425     cl = Clogger.new(app, :logger => str)
 426     assert_raise(TypeError) { cl.call(@req) }
 427     str = str.string
 428     e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
 429     assert_match %r{#{e}$}m, str
 430   end
 431
 432   def test_broken_header_response
 433     str = StringIO.new
 434     app = lambda { |env| [302, [ %w(a) ], []] }
 435     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 436     assert_nothing_raised { cl.call(@req) }
 437   end
 438
 439   def test_subclass_hash
 440     str = StringIO.new
 441     req = Rack::Utils::HeaderHash.new(@req)
 442     app = lambda { |env| [302, [ %w(a) ], []] }
 443     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 444     assert_nothing_raised { cl.call(req).last.each {}.close }
 445     assert str.size > 0
 446   end
 447
 448   def test_subclassed_string_req
 449     str = StringIO.new
 450     req = {}
 451     @req.each { |key,value|
 452       req[FooString.new(key)] = value.kind_of?(String) ?
 453                                 FooString.new(value) : value
 454     }
 455     app = lambda { |env| [302, [ %w(a) ], []] }
 456     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 457     assert_nothing_raised { cl.call(req).last.each {}.close }
 458     assert str.size > 0
 459   end
 460
 461   def test_subclassed_string_in_body
 462     str = StringIO.new
 463     body = "hello"
 464     r = nil
 465     app = lambda { |env| [302, [ %w(a) ], [FooString.new(body)]] }
 466     cl = Clogger.new(app, :logger => str, :format => '$body_bytes_sent')
 467     assert_nothing_raised { cl.call(@req).last.each { |x| r = x }.close }
 468     assert str.size > 0
 469     assert_equal body.size.to_s << "\n", str.string
 470     assert_equal r, body
 471     assert r.object_id != body.object_id
 472   end
 473
 474   def test_http_09_request
 475     str = StringIO.new
 476     app = lambda { |env| [302, [ %w(a) ], []] }
 477     cl = Clogger.new(app, :logger => str, :format => '$request')
 478     req = @req.dup
 479     req.delete 'HTTP_VERSION'
 480     cl.call(req)
 481     assert_equal "GET /hello?goodbye=true\n", str.string
 482   end
 483
 484   def test_request_method_only
 485     str = StringIO.new
 486     app = lambda { |env| [302, [ %w(a) ], []] }
 487     cl = Clogger.new(app, :logger => str, :format => '$request_method')
 488     cl.call(@req)
 489     assert_equal "GET\n", str.string
 490   end
 491
 492   def test_content_length_null
 493     str = StringIO.new
 494     app = lambda { |env| [302, [ %w(a) ], []] }
 495     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 496     cl.call(@req)
 497     assert_equal "-\n", str.string
 498   end
 499
 500   def test_content_length_set
 501     str = StringIO.new
 502     app = lambda { |env| [302, [ %w(a) ], []] }
 503     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 504     cl.call(@req.merge('CONTENT_LENGTH' => '5'))
 505     assert_equal "5\n", str.string
 506   end
 507
 508   def test_http_content_type_fallback
 509     str = StringIO.new
 510     app = lambda { |env| [302, [ %w(a) ], []] }
 511     cl = Clogger.new(app, :logger => str, :format => '$http_content_type')
 512     cl.call(@req.merge('CONTENT_TYPE' => 'text/plain'))
 513     assert_equal "text/plain\n", str.string
 514   end
 515
 516   def test_clogger_synced
 517     io = StringIO.new
 518     logger = Struct.new(:sync, :io).new(false, io)
 519     assert ! logger.sync
 520     def logger.<<(str)
 521       io << str
 522     end
 523     app = lambda { |env| [302, [ %w(a) ], []] }
 524     cl = Clogger.new(app, :logger => logger)
 525     assert logger.sync
 526   end
 527
 528   def test_clogger_unsyncable
 529     logger = ''
 530     assert ! logger.respond_to?('sync=')
 531     app = lambda { |env| [302, [ %w(a) ], []] }
 532     assert_nothing_raised { Clogger.new(app, :logger => logger) }
 533   end
 534
 535   def test_clogger_no_ORS
 536     s = ''
 537     app = lambda { |env| [302, [ %w(a) ], []] }
 538     cl = Clogger.new(app, :logger => s, :format => "$request", :ORS => "")
 539     cl.call(@req)
 540     assert_equal "GET /hello?goodbye=true HTTP/1.0", s
 541   end
 542
 543   def test_clogger_weird_ORS
 544     s = ''
 545     app = lambda { |env| [302, [ %w(a) ], []] }
 546     cl = Clogger.new(app, :logger => s, :format => "<$request", :ORS => ">")
 547     cl.call(@req)
 548     assert_equal "<GET /hello?goodbye=true HTTP/1.0>", s
 549   end
 550
 551   def test_clogger_body_not_closeable
 552     s = ''
 553     app = lambda { |env| [302, [ %w(a) ], []] }
 554     cl = Clogger.new(app, :logger => s)
 555     status, headers, body = cl.call(@req)
 556     assert_nil body.close
 557   end
 558
 559   def test_clogger_response_frozen
 560     response = [ 200, { "AAAA" => "AAAA"}.freeze, [].freeze ].freeze
 561     s = StringIO.new("")
 562     app = Rack::Builder.new do
 563       use Clogger, :logger => s, :format => "$request_time $http_host"
 564       run lambda { |env| response }
 565     end
 566     assert_nothing_raised do
 567       3.times do
 568         resp = app.call(@req)
 569         assert ! resp.frozen?
 570         resp.last.each { |x| }
 571       end
 572     end
 573   end
 574
 575   def test_clogger_body_close_return_value
 576     s = ''
 577     body = []
 578     def body.close
 579       :foo
 580     end
 581     app = lambda { |env| [302, [ %w(a) ], body ] }
 582     cl = Clogger.new(app, :logger => s)
 583     status, headers, body = cl.call(@req)
 584     assert_equal :foo, body.close
 585   end
 586
 587   def test_clogger_auto_reentrant_true
 588     s = ''
 589     body = []
 590     app = lambda { |env| [302, [ %w(a) ], body ] }
 591     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 592     @req['rack.multithread'] = true
 593     status, headers, body = cl.call(@req)
 594     assert cl.reentrant?
 595   end
 596
 597   def test_clogger_auto_reentrant_false
 598     s = ''
 599     body = []
 600     app = lambda { |env| [302, [ %w(a) ], body ] }
 601     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 602     @req['rack.multithread'] = false
 603     status, headers, body = cl.call(@req)
 604     assert ! cl.reentrant?
 605   end
 606
 607   def test_clogger_auto_reentrant_forced_true
 608     s = ''
 609     body = []
 610     app = lambda { |env| [302, [ %w(a) ], body ] }
 611     o = { :logger => s, :format => "$request_time", :reentrant => true }
 612     cl = Clogger.new(app, o)
 613     @req['rack.multithread'] = false
 614     status, headers, body = cl.call(@req)
 615     assert cl.reentrant?
 616   end
 617
 618   def test_clogger_auto_reentrant_forced_false
 619     s = ''
 620     body = []
 621     app = lambda { |env| [302, [ %w(a) ], body ] }
 622     o = { :logger => s, :format => "$request_time", :reentrant => false }
 623     cl = Clogger.new(app, o)
 624     @req['rack.multithread'] = true
 625     status, headers, body = cl.call(@req)
 626     assert ! cl.reentrant?
 627   end
 628
 629   def test_invalid_status
 630     s = []
 631     body = []
 632     app = lambda { |env| [ env["force.status"], [ %w(a b) ], body ] }
 633     o = { :logger => s, :format => "$status" }
 634     cl = Clogger.new(app, o)
 635     status, headers, body = cl.call(@req.merge("force.status" => -1))
 636     assert_equal -1, status
 637     assert_equal "-\n", s.last
 638     status, headers, body = cl.call(@req.merge("force.status" => 1000))
 639     assert_equal 1000, status
 640     assert_equal "-\n", s.last
 641     u64_max = 0xffffffffffffffff
 642     status, headers, body = cl.call(@req.merge("force.status" => u64_max))
 643     assert_equal u64_max, status
 644     assert_equal "-\n", s.last
 645   end
 646
 647   # so we don't  care about the portability of this test
 648   # if it doesn't leak on Linux, it won't leak anywhere else
 649   # unless your C compiler or platform is otherwise broken
 650   LINUX_PROC_PID_STATUS = "/proc/self/status"
 651   def test_memory_leak
 652     app = lambda { |env| [ 0, {}, [] ] }
 653     clogger = Clogger.new(app, :logger => $stderr)
 654     match_rss = /^VmRSS:\s+(\d+)/
 655     if File.read(LINUX_PROC_PID_STATUS) =~ match_rss
 656       before = $1.to_i
 657       1000000.times { clogger.dup }
 658       File.read(LINUX_PROC_PID_STATUS) =~ match_rss
 659       after = $1.to_i
 660       diff = after - before
 661       assert(diff < 10000, "memory grew more than 10M: #{diff}")
 662     end
 663   end if RUBY_PLATFORM =~ /linux/ && File.readable?(LINUX_PROC_PID_STATUS)
 664
 665   def test_path_open_file
 666     tmp = Tempfile.new('test_clogger')
 667     app = lambda { |env| [ 200, {}, [] ] }
 668     app = Clogger.new(app, :format => '$status', :path => tmp.path)
 669     assert_kind_of Integer, app.fileno
 670     assert app.fileno != tmp.fileno
 671     status, headers, body = app.call(@req)
 672     assert_equal "200\n", tmp.read
 673   end
 674
 675   def test_path_logger_conflict
 676     tmp = Tempfile.new('test_clogger')
 677     app = lambda { |env| [ 200, {}, [] ] }
 678     assert_raises(ArgumentError) {
 679       Clogger.new(app, :logger=> $stderr, :path => tmp.path)
 680     }
 681   end
 682
 683   def test_request_time
 684     s = []
 685     app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
 686     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 687     status, headers, body = cl.call(@req)
 688     assert_nothing_raised { body.each { |x| } ; body.close }
 689     assert s[-1].to_f >= 0.100
 690     assert s[-1].to_f <= 0.110
 691   end
 692
 693   def test_insanely_long_time_format
 694     s = []
 695     app = lambda { |env| [200, [], [] ] }
 696     fmt = '%Y' * 100
 697     expect = Time.now.utc.strftime(fmt) << "\n"
 698     assert_equal 100 * 4 + 1, expect.size
 699     cl = Clogger.new(app, :logger => s, :format => "$time_utc{#{fmt}}")
 700     status, headers, body = cl.call(@req)
 701     assert_equal expect, s[0]
 702   end
 703
 704   def test_time_utc
 705     s = []
 706     app = lambda { |env| [200, [], [] ] }
 707     cl = Clogger.new(app, :logger => s, :format => "$time_utc")
 708     status, headers, body = cl.call(@req)
 709     assert %r!\A\d+/\w+/\d{4}:\d\d:\d\d:\d\d \+0000\n\z! =~ s[0], s.inspect
 710   end
 711
 712   def test_time_iso8601
 713     s = []
 714     app = lambda { |env| [200, [], [] ] }
 715     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 716     status, headers, body = cl.call(@req)
 717     t = Time.parse(s[0])
 718     assert_equal t.iso8601, s[0].strip
 719   end
 720
 721   def test_time_iso8601_pst8pdt
 722     ENV["TZ"] = "PST8PDT"
 723     s = []
 724     app = lambda { |env| [200, [], [] ] }
 725     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 726     status, headers, body = cl.call(@req)
 727     t = Time.parse(s[0])
 728     assert_equal t.iso8601, s[0].strip
 729   end
 730
 731   def test_time_iso8601_utc
 732     ENV["TZ"] = "UTC"
 733     s = []
 734     app = lambda { |env| [200, [], [] ] }
 735     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 736     status, headers, body = cl.call(@req)
 737     t = Time.parse(s[0])
 738     assert_equal t.iso8601, s[0].strip
 739   end
 740
 741   def test_time_local
 742     s = []
 743     app = lambda { |env| [200, [], [] ] }
 744     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 745     status, headers, body = cl.call(@req)
 746     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 747     assert_equal t.strftime(@nginx_fmt), s[0].strip
 748   end
 749
 750   def test_time_local_pst8pdt
 751     orig = ENV["TZ"]
 752     ENV["TZ"] = "PST8PDT"
 753     s = []
 754     app = lambda { |env| [200, [], [] ] }
 755     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 756     status, headers, body = cl.call(@req)
 757     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 758     assert_equal t.strftime(@nginx_fmt), s[0].strip
 759   end
 760
 761   def test_time_local_utc
 762     ENV["TZ"] = "UTC"
 763     s = []
 764     app = lambda { |env| [200, [], [] ] }
 765     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 766     status, headers, body = cl.call(@req)
 767     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 768     assert_equal t.strftime(@nginx_fmt), s[0].strip
 769   end
 770
 771   def test_method_missing
 772     s = []
 773     body = []
 774     def body.foo_bar(foo)
 775       [ foo.to_s ]
 776     end
 777     def body.noargs
 778       :hello
 779     end
 780     def body.omg(&block)
 781       yield :PONIES
 782     end
 783     app = lambda { |env| [200, [], body ] }
 784     cl = Clogger.new(app, :logger => s, :format => '$body_bytes_sent')
 785     status, headers, body = cl.call(@req)
 786     assert_nothing_raised do
 787       body.each { |x| s << x }
 788       body.close
 789     end
 790     assert_equal "0\n", s[0], s.inspect
 791     assert_kind_of Clogger, body
 792     assert_equal %w(1), body.foo_bar(1)
 793     assert_equal :hello, body.noargs
 794     body.omg { |x| s << x }
 795     assert_equal :PONIES, s[1]
 796     assert_equal 2, s.size
 797   end
 798 end