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       "rack.url_scheme" => "http",
  32       "REMOTE_ADDR" => 'home',
  33     }
  34   end
  35
  36   def teardown
  37     ENV["TZ"] = @tz
  38   end
  39
  40   def test_init_basic
  41     Clogger.new(lambda { |env| [ 0, {}, [] ] })
  42   end
  43
  44   def test_init_noargs
  45     assert_raise(ArgumentError) { Clogger.new }
  46   end
  47
  48   def test_clogger_sym_format
  49     app = lambda { |env| [ 0, {}, [] ] }
  50     tmp = Clogger.new app, :format => :Rack_1_0, :logger => $stderr
  51   end
  52
  53   def test_init_stderr
  54     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => $stderr)
  55     assert_kind_of(Integer, cl.fileno)
  56     assert_equal $stderr.fileno, cl.fileno
  57   end
  58
  59   def test_init_stringio
  60     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => StringIO.new)
  61     assert_nil cl.fileno
  62   end
  63
  64   def test_write_stringio
  65     start = DateTime.now - 1
  66     str = StringIO.new
  67     cl = Clogger.new(lambda { |env| [ "302 Found", {}, [] ] }, :logger => str)
  68     status, headers, body = cl.call(@req)
  69     assert_equal("302 Found", status)
  70     assert_equal({}, headers)
  71     body.each { |part| assert false }
  72     body.close
  73     str = str.string
  74     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 302 -\n\z}
  75     assert_match r, str
  76     %r{\[([^\]]+)\]} =~ str
  77     tmp = nil
  78     assert_nothing_raised {
  79       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
  80     }
  81     assert tmp >= start
  82     assert tmp <= DateTime.now
  83   end
  84
  85   def test_clen_stringio
  86     start = DateTime.now - 1
  87     str = StringIO.new
  88     app = lambda { |env| [ 301, {'Content-Length' => '5'}, ['abcde'] ] }
  89     format = Common.dup
  90     assert format.gsub!(/response_length/, 'sent_http_content_length')
  91     cl = Clogger.new(app, :logger => str, :format => format)
  92     status, headers, body = cl.call(@req)
  93     assert_equal(301, status)
  94     assert_equal({'Content-Length' => '5'}, headers)
  95     body.each { |part| assert_equal('abcde', part) }
  96     str = str.string
  97     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 301 5\n\z}
  98     assert_match r, str
  99     %r{\[([^\]]+)\]} =~ str
 100     tmp = nil
 101     assert_nothing_raised {
 102       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
 103     }
 104     assert tmp >= start
 105     assert tmp <= DateTime.now
 106   end
 107
 108   def test_compile_ambiguous
 109     cl = Clogger.new(nil, :logger => $stderr)
 110     ary = nil
 111     cl.instance_eval {
 112       ary = compile_format(
 113         '$remote_addr $$$$pid' \
 114         "\n")
 115     }
 116     expect = [
 117       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 118       [ Clogger::OP_LITERAL, " " ],
 119       [ Clogger::OP_LITERAL, "$$$" ],
 120       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:pid] ],
 121       [ Clogger::OP_LITERAL, "\n" ],
 122       ]
 123     assert_equal expect, ary
 124   end
 125
 126   def test_compile_auto_newline
 127     cl = Clogger.new(nil, :logger => $stderr)
 128     ary = nil
 129     cl.instance_eval { ary = compile_format('$remote_addr $request') }
 130     expect = [
 131       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 132       [ Clogger::OP_LITERAL, " " ],
 133       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
 134       [ Clogger::OP_LITERAL, "\n" ],
 135       ]
 136     assert_equal expect, ary
 137   end
 138
 139   def test_big_log
 140     str = StringIO.new
 141     fmt = '$remote_addr $pid $remote_user [$time_local] ' \
 142           '"$request" $status $body_bytes_sent "$http_referer" ' \
 143          '"$http_user_agent" "$http_cookie" $request_time $http_host'
 144     app = lambda { |env| [ 302, {}, [] ] }
 145     cl = Clogger.new(app, :logger => str, :format => fmt)
 146     cookie = "foo=bar#{'f' * 256}".freeze
 147     req = {
 148       'HTTP_HOST' => 'example.com:12345',
 149       'HTTP_COOKIE' => cookie,
 150     }
 151     req = @req.merge(req)
 152     body = cl.call(req).last
 153     body.each { |part| part }
 154     body.close
 155     str = str.string
 156     assert(str.size > 128)
 157     assert_match %r["echo and socat \\o/" "#{cookie}" \d+\.\d{3}], str
 158     assert_match %r["#{cookie}" \d+\.\d{3} example\.com:12345\n\z], str
 159   end
 160
 161   def test_compile
 162     cl = Clogger.new(nil, :logger => $stderr)
 163     ary = nil
 164     cl.instance_eval {
 165       ary = compile_format(
 166         '$remote_addr - $remote_user [$time_local] ' \
 167         '"$request" $status $body_bytes_sent "$http_referer" ' \
 168         '"$http_user_agent" "$http_cookie" $request_time ' \
 169         '$env{rack.url_scheme}' \
 170         "\n")
 171     }
 172     expect = [
 173       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 174       [ Clogger::OP_LITERAL, " - " ],
 175       [ Clogger::OP_REQUEST, "REMOTE_USER" ],
 176       [ Clogger::OP_LITERAL, " [" ],
 177       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:time_local] ],
 178       [ Clogger::OP_LITERAL, "] \"" ],
 179       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
 180       [ Clogger::OP_LITERAL, "\" "],
 181       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:status] ],
 182       [ Clogger::OP_LITERAL, " "],
 183       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:body_bytes_sent] ],
 184       [ Clogger::OP_LITERAL, " \"" ],
 185       [ Clogger::OP_REQUEST, "HTTP_REFERER" ],
 186       [ Clogger::OP_LITERAL, "\" \"" ],
 187       [ Clogger::OP_REQUEST, "HTTP_USER_AGENT" ],
 188       [ Clogger::OP_LITERAL, "\" \"" ],
 189       [ Clogger::OP_REQUEST, "HTTP_COOKIE" ],
 190       [ Clogger::OP_LITERAL, "\" " ],
 191       [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000 ],
 192       [ Clogger::OP_LITERAL, " " ],
 193       [ Clogger::OP_REQUEST, "rack.url_scheme" ],
 194       [ Clogger::OP_LITERAL, "\n" ],
 195     ]
 196     assert_equal expect, ary
 197   end
 198
 199   def test_eval
 200     current = Thread.current.to_s
 201     str = StringIO.new
 202     app = lambda { |env| [ 302, {}, [] ] }
 203     cl = Clogger.new(app,
 204                     :logger => str,
 205                     :format => "-$e{Thread.current}-\n")
 206     status, headers, body = cl.call(@req)
 207     assert_equal "-#{current}-\n", str.string
 208   end
 209
 210   def test_pid
 211     str = StringIO.new
 212     app = lambda { |env| [ 302, {}, [] ] }
 213     cl = Clogger.new(app, :logger => str, :format => "[$pid]\n")
 214     status, headers, body = cl.call(@req)
 215     assert_equal "[#$$]\n", str.string
 216   end
 217
 218   def test_rack_xff
 219     str = StringIO.new
 220     app = lambda { |env| [ 302, {}, [] ] }
 221     cl = Clogger.new(app, :logger => str, :format => "$ip")
 222     req = @req.merge("HTTP_X_FORWARDED_FOR" => '192.168.1.1')
 223     status, headers, body = cl.call(req)
 224     assert_equal "192.168.1.1\n", str.string
 225
 226     str = StringIO.new
 227     cl = Clogger.new(app, :logger => str, :format => "$ip")
 228     status, headers, body = cl.call(@req)
 229     assert_equal "home\n", str.string
 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_escape_crazy_delete
 393     str = StringIO.new
 394     app = lambda { |env| [302, {}, [] ] }
 395     cl = Clogger.new(app, :logger => str, :format => "$http_cookie")
 396     @req["HTTP_COOKIE"] = "a\x7f\xff"
 397     cl.call(@req)
 398     assert_equal "a\\x7F\\xFF\n", str.string
 399   end
 400
 401   def test_request_uri_fallback
 402     str = StringIO.new
 403     app = lambda { |env| [ 200, {}, [] ] }
 404     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 405     status, headers, body = cl.call(@req)
 406     assert_equal "/hello?goodbye=true\n", str.string
 407   end
 408
 409   def test_request_uri_set
 410     str = StringIO.new
 411     app = lambda { |env| [ 200, {}, [] ] }
 412     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 413     status, headers, body = cl.call(@req.merge("REQUEST_URI" => '/zzz'))
 414     assert_equal "/zzz\n", str.string
 415   end
 416
 417   def test_cookies
 418     str = StringIO.new
 419     app = lambda { |env|
 420       req = Rack::Request.new(env).cookies
 421       [ 302, {}, [] ]
 422     }
 423     cl = Clogger.new(app,
 424         :format => '$cookie_foo $cookie_quux',
 425         :logger => str)
 426     req = @req.merge('HTTP_COOKIE' => "foo=bar;quux=h%7F&m")
 427     status, headers, body = cl.call(req)
 428     assert_equal "bar h\\x7F&m\n", str.string
 429   end
 430
 431   def test_bogus_app_response
 432     str = StringIO.new
 433     app = lambda { |env| 302 }
 434     cl = Clogger.new(app, :logger => str)
 435     assert_raise(TypeError) { cl.call(@req) }
 436     str = str.string
 437     e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
 438     assert_match %r{#{e}$}m, str
 439   end
 440
 441   def test_broken_header_response
 442     str = StringIO.new
 443     app = lambda { |env| [302, [ %w(a) ], []] }
 444     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 445     assert_nothing_raised { cl.call(@req) }
 446   end
 447
 448   def test_subclass_hash
 449     str = StringIO.new
 450     req = Rack::Utils::HeaderHash.new(@req)
 451     app = lambda { |env| [302, [ %w(a) ], []] }
 452     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 453     assert_nothing_raised { cl.call(req).last.each {}.close }
 454     assert str.size > 0
 455   end
 456
 457   def test_subclassed_string_req
 458     str = StringIO.new
 459     req = {}
 460     @req.each { |key,value|
 461       req[FooString.new(key)] = value.kind_of?(String) ?
 462                                 FooString.new(value) : value
 463     }
 464     app = lambda { |env| [302, [ %w(a) ], []] }
 465     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 466     assert_nothing_raised { cl.call(req).last.each {}.close }
 467     assert str.size > 0
 468   end
 469
 470   def test_subclassed_string_in_body
 471     str = StringIO.new
 472     body = "hello"
 473     r = nil
 474     app = lambda { |env| [302, [ %w(a) ], [FooString.new(body)]] }
 475     cl = Clogger.new(app, :logger => str, :format => '$body_bytes_sent')
 476     assert_nothing_raised { cl.call(@req).last.each { |x| r = x }.close }
 477     assert str.size > 0
 478     assert_equal body.size.to_s << "\n", str.string
 479     assert_equal r, body
 480     assert r.object_id != body.object_id
 481   end
 482
 483   # Rack::BodyProxy does this thing with method_missing
 484   # This test fails under MRI 1.9.1 and 1.9.2, but works under 1.9.3
 485   def test_each_with_external_block
 486     foo = Object.new
 487     foo.instance_variable_set(:@body, ["BodyProxy"])
 488     def foo.method_missing(*args, &block)
 489       @body.__send__(*args, &block)
 490     end
 491     app = lambda { |env| [302, [], foo] }
 492     str = StringIO.new
 493     cl = Clogger.new(app, :logger => str, :format => '$body_bytes_sent')
 494     r = nil
 495     assert_nothing_raised { r = cl.call(@req) }
 496     body = []
 497     r[2].each { |x| body << x }
 498     r[2].close
 499     assert_equal %w(BodyProxy), body
 500     assert_equal "9\n", str.string
 501   end
 502
 503   def test_http_09_request
 504     str = StringIO.new
 505     app = lambda { |env| [302, [ %w(a) ], []] }
 506     cl = Clogger.new(app, :logger => str, :format => '$request')
 507     req = @req.dup
 508     req.delete 'HTTP_VERSION'
 509     cl.call(req)
 510     assert_equal "GET /hello?goodbye=true\n", str.string
 511   end
 512
 513   def test_request_method_only
 514     str = StringIO.new
 515     app = lambda { |env| [302, [ %w(a) ], []] }
 516     cl = Clogger.new(app, :logger => str, :format => '$request_method')
 517     cl.call(@req)
 518     assert_equal "GET\n", str.string
 519   end
 520
 521   def test_content_length_null
 522     str = StringIO.new
 523     app = lambda { |env| [302, [ %w(a) ], []] }
 524     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 525     cl.call(@req)
 526     assert_equal "-\n", str.string
 527   end
 528
 529   def test_content_length_set
 530     str = StringIO.new
 531     app = lambda { |env| [302, [ %w(a) ], []] }
 532     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 533     cl.call(@req.merge('CONTENT_LENGTH' => '5'))
 534     assert_equal "5\n", str.string
 535   end
 536
 537   def test_http_content_type_fallback
 538     str = StringIO.new
 539     app = lambda { |env| [302, [ %w(a) ], []] }
 540     cl = Clogger.new(app, :logger => str, :format => '$http_content_type')
 541     cl.call(@req.merge('CONTENT_TYPE' => 'text/plain'))
 542     assert_equal "text/plain\n", str.string
 543   end
 544
 545   def test_clogger_synced
 546     io = StringIO.new
 547     logger = Struct.new(:sync, :io).new(false, io)
 548     assert ! logger.sync
 549     def logger.<<(str)
 550       io << str
 551     end
 552     app = lambda { |env| [302, [ %w(a) ], []] }
 553     cl = Clogger.new(app, :logger => logger)
 554     assert logger.sync
 555   end
 556
 557   def test_clogger_unsyncable
 558     logger = ''
 559     assert ! logger.respond_to?('sync=')
 560     app = lambda { |env| [302, [ %w(a) ], []] }
 561     assert_nothing_raised { Clogger.new(app, :logger => logger) }
 562   end
 563
 564   def test_clogger_no_ORS
 565     s = ''
 566     app = lambda { |env| [302, [ %w(a) ], []] }
 567     cl = Clogger.new(app, :logger => s, :format => "$request", :ORS => "")
 568     cl.call(@req)
 569     assert_equal "GET /hello?goodbye=true HTTP/1.0", s
 570   end
 571
 572   def test_clogger_weird_ORS
 573     s = ''
 574     app = lambda { |env| [302, [ %w(a) ], []] }
 575     cl = Clogger.new(app, :logger => s, :format => "<$request", :ORS => ">")
 576     cl.call(@req)
 577     assert_equal "<GET /hello?goodbye=true HTTP/1.0>", s
 578   end
 579
 580   def test_clogger_body_not_closeable
 581     s = ''
 582     app = lambda { |env| [302, [ %w(a) ], []] }
 583     cl = Clogger.new(app, :logger => s)
 584     status, headers, body = cl.call(@req)
 585     assert_nil body.close
 586   end
 587
 588   def test_clogger_response_frozen
 589     response = [ 200, { "AAAA" => "AAAA"}.freeze, [].freeze ].freeze
 590     s = StringIO.new("")
 591     app = Rack::Builder.new do
 592       use Clogger, :logger => s, :format => "$request_time $http_host"
 593       run lambda { |env| response }
 594     end
 595     assert_nothing_raised do
 596       3.times do
 597         resp = app.call(@req)
 598         assert ! resp.frozen?
 599         resp.last.each { |x| }
 600       end
 601     end
 602   end
 603
 604   def test_clogger_body_close_return_value
 605     s = ''
 606     body = []
 607     def body.close
 608       :foo
 609     end
 610     app = lambda { |env| [302, [ %w(a) ], body ] }
 611     cl = Clogger.new(app, :logger => s)
 612     status, headers, body = cl.call(@req)
 613     assert_equal :foo, body.close
 614   end
 615
 616   def test_clogger_auto_reentrant_true
 617     s = ''
 618     body = []
 619     app = lambda { |env| [302, [ %w(a) ], body ] }
 620     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 621     @req['rack.multithread'] = true
 622     status, headers, body = cl.call(@req)
 623     assert cl.reentrant?
 624   end
 625
 626   def test_clogger_auto_reentrant_false
 627     s = ''
 628     body = []
 629     app = lambda { |env| [302, [ %w(a) ], body ] }
 630     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 631     @req['rack.multithread'] = false
 632     status, headers, body = cl.call(@req)
 633     assert ! cl.reentrant?
 634   end
 635
 636   def test_clogger_auto_reentrant_forced_true
 637     s = ''
 638     body = []
 639     app = lambda { |env| [302, [ %w(a) ], body ] }
 640     o = { :logger => s, :format => "$request_time", :reentrant => true }
 641     cl = Clogger.new(app, o)
 642     @req['rack.multithread'] = false
 643     status, headers, body = cl.call(@req)
 644     assert cl.reentrant?
 645   end
 646
 647   def test_clogger_auto_reentrant_forced_false
 648     s = ''
 649     body = []
 650     app = lambda { |env| [302, [ %w(a) ], body ] }
 651     o = { :logger => s, :format => "$request_time", :reentrant => false }
 652     cl = Clogger.new(app, o)
 653     @req['rack.multithread'] = true
 654     status, headers, body = cl.call(@req)
 655     assert ! cl.reentrant?
 656   end
 657
 658   def test_invalid_status
 659     s = []
 660     body = []
 661     app = lambda { |env| [ env["force.status"], [ %w(a b) ], body ] }
 662     o = { :logger => s, :format => "$status" }
 663     cl = Clogger.new(app, o)
 664     status, headers, body = cl.call(@req.merge("force.status" => -1))
 665     assert_equal -1, status
 666     assert_equal "-\n", s.last
 667     status, headers, body = cl.call(@req.merge("force.status" => 1000))
 668     assert_equal 1000, status
 669     assert_equal "-\n", s.last
 670     u64_max = 0xffffffffffffffff
 671     status, headers, body = cl.call(@req.merge("force.status" => u64_max))
 672     assert_equal u64_max, status
 673     assert_equal "-\n", s.last
 674   end
 675
 676   # so we don't  care about the portability of this test
 677   # if it doesn't leak on Linux, it won't leak anywhere else
 678   # unless your C compiler or platform is otherwise broken
 679   LINUX_PROC_PID_STATUS = "/proc/self/status"
 680   def test_memory_leak
 681     app = lambda { |env| [ 0, {}, [] ] }
 682     clogger = Clogger.new(app, :logger => $stderr)
 683     match_rss = /^VmRSS:\s+(\d+)/
 684     if File.read(LINUX_PROC_PID_STATUS) =~ match_rss
 685       before = $1.to_i
 686       1000000.times { clogger.dup }
 687       File.read(LINUX_PROC_PID_STATUS) =~ match_rss
 688       after = $1.to_i
 689       diff = after - before
 690       assert(diff < 10000, "memory grew more than 10M: #{diff}")
 691     end
 692   end if RUBY_PLATFORM =~ /linux/ && File.readable?(LINUX_PROC_PID_STATUS)
 693
 694   def test_path_open_file
 695     tmp = Tempfile.new('test_clogger')
 696     app = lambda { |env| [ 200, {}, [] ] }
 697     app = Clogger.new(app, :format => '$status', :path => tmp.path)
 698     assert_kind_of Integer, app.fileno
 699     assert app.fileno != tmp.fileno
 700     status, headers, body = app.call(@req)
 701     assert_equal "200\n", tmp.read
 702   end
 703
 704   def test_path_logger_conflict
 705     tmp = Tempfile.new('test_clogger')
 706     app = lambda { |env| [ 200, {}, [] ] }
 707     assert_raises(ArgumentError) {
 708       Clogger.new(app, :logger=> $stderr, :path => tmp.path)
 709     }
 710   end
 711
 712   def test_request_time
 713     s = []
 714     app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
 715     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 716     status, headers, body = cl.call(@req)
 717     assert_nothing_raised { body.each { |x| } ; body.close }
 718     assert s[-1].to_f >= 0.100
 719     assert s[-1].to_f <= 0.110
 720   end
 721
 722   def test_insanely_long_time_format
 723     s = []
 724     app = lambda { |env| [200, [], [] ] }
 725     fmt = '%Y' * 100
 726     expect = Time.now.utc.strftime(fmt) << "\n"
 727     assert_equal 100 * 4 + 1, expect.size
 728     cl = Clogger.new(app, :logger => s, :format => "$time_utc{#{fmt}}")
 729     status, headers, body = cl.call(@req)
 730     assert_equal expect, s[0]
 731   end
 732
 733   def test_time_utc
 734     s = []
 735     app = lambda { |env| [200, [], [] ] }
 736     cl = Clogger.new(app, :logger => s, :format => "$time_utc")
 737     status, headers, body = cl.call(@req)
 738     assert %r!\A\d+/\w+/\d{4}:\d\d:\d\d:\d\d \+0000\n\z! =~ s[0], s.inspect
 739   end
 740
 741   def test_time_iso8601
 742     s = []
 743     app = lambda { |env| [200, [], [] ] }
 744     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 745     status, headers, body = cl.call(@req)
 746     t = Time.parse(s[0])
 747     assert_equal t.iso8601, s[0].strip
 748   end
 749
 750   def test_time_iso8601_pst8pdt
 751     ENV["TZ"] = "PST8PDT"
 752     s = []
 753     app = lambda { |env| [200, [], [] ] }
 754     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 755     status, headers, body = cl.call(@req)
 756     t = Time.parse(s[0])
 757     assert_equal t.iso8601, s[0].strip
 758   end
 759
 760   def test_time_iso8601_utc
 761     ENV["TZ"] = "UTC"
 762     s = []
 763     app = lambda { |env| [200, [], [] ] }
 764     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 765     status, headers, body = cl.call(@req)
 766     t = Time.parse(s[0])
 767     assert_equal t.iso8601, s[0].strip
 768   end
 769
 770   def test_time_local
 771     s = []
 772     app = lambda { |env| [200, [], [] ] }
 773     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 774     status, headers, body = cl.call(@req)
 775     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 776     assert_equal t.strftime(@nginx_fmt), s[0].strip
 777   end
 778
 779   def test_time_local_pst8pdt
 780     orig = ENV["TZ"]
 781     ENV["TZ"] = "PST8PDT"
 782     s = []
 783     app = lambda { |env| [200, [], [] ] }
 784     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 785     status, headers, body = cl.call(@req)
 786     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 787     assert_equal t.strftime(@nginx_fmt), s[0].strip
 788   end
 789
 790   def test_time_local_utc
 791     ENV["TZ"] = "UTC"
 792     s = []
 793     app = lambda { |env| [200, [], [] ] }
 794     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 795     status, headers, body = cl.call(@req)
 796     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 797     assert_equal t.strftime(@nginx_fmt), s[0].strip
 798   end
 799
 800   def test_method_missing
 801     s = []
 802     body = []
 803     def body.foo_bar(foo)
 804       [ foo.to_s ]
 805     end
 806     def body.noargs
 807       :hello
 808     end
 809     def body.omg(&block)
 810       yield :PONIES
 811     end
 812     app = lambda { |env| [200, [], body ] }
 813     cl = Clogger.new(app, :logger => s, :format => '$body_bytes_sent')
 814     status, headers, body = cl.call(@req)
 815     assert_nothing_raised do
 816       body.each { |x| s << x }
 817       body.close
 818     end
 819     assert_equal "0\n", s[0], s.inspect
 820     assert_kind_of Clogger, body
 821     assert_equal %w(1), body.foo_bar(1)
 822     assert_equal :hello, body.noargs
 823     body.omg { |x| s << x }
 824     assert_equal :PONIES, s[1]
 825     assert_equal 2, s.size
 826   end
 827
 828   def test_full_uri
 829     s = []
 830     format = '"$request_method ' \
 831              '$env{rack.url_scheme}://$http_host$request_uri $http_version"'
 832     app = lambda { |env| [200, [], [] ] }
 833     cl = Clogger.new(app, :logger => s, :format => format)
 834     @req["HTTP_HOST"] = "example.com"
 835     status, headers, body = cl.call(@req)
 836     expect = "\"GET http://example.com/hello?goodbye=true HTTP/1.0\"\n"
 837     assert_equal [ expect ], s
 838   end
 839
 840   def test_lint_error_wrapper
 841     require 'rack/lobster'
 842     @req["SERVER_NAME"] = "FOO"
 843     @req["SERVER_PORT"] = "666"
 844     @req["rack.version"] = [1,1]
 845     @req["rack.multithread"] = true
 846     @req["rack.multiprocess"] = true
 847     @req["rack.run_once"] = false
 848     app = Rack::ContentLength.new(Rack::ContentType.new(Rack::Lobster.new))
 849     cl = Clogger.new(app, :format => :Combined)
 850     @req["rack.errors"] = err = StringIO.new
 851     status, headers, body = r = Rack::Lint.new(cl).call(@req)
 852     body.each { |x| assert_kind_of String, x.to_str }
 853     body.close # might raise here
 854     assert_match(%r{GET /hello}, err.string)
 855   end
 856 end