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     str.rewind
 226     str.truncate(0)
 227     status, headers, body = cl.call(@req)
 228     assert_equal "home\n", str.string
 229     str.rewind
 230     str.truncate(0)
 231   end
 232
 233   def test_rack_1_0
 234     start = DateTime.now - 1
 235     str = StringIO.new
 236     app = lambda { |env| [ 200, {'Content-Length'=>'0'}, %w(a b c)] }
 237     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 238     status, headers, body = cl.call(@req)
 239     tmp = []
 240     body.each { |s| tmp << s }
 241     body.close
 242     assert_equal %w(a b c), tmp
 243     str = str.string
 244     assert_match %r[" 200 3 \d+\.\d{4}\n\z], str
 245     tmp = nil
 246     %r{\[(\d+/\w+/\d+ \d+:\d+:\d+)\]} =~ str
 247     assert $1
 248     assert_nothing_raised { tmp = DateTime.strptime($1, "%d/%b/%Y %H:%M:%S") }
 249     assert tmp >= start
 250     assert tmp <= DateTime.now
 251   end
 252
 253   def test_msec
 254     str = StringIO.new
 255     app = lambda { |env| [ 200, {}, [] ] }
 256     cl = Clogger.new(app, :logger => str, :format => '$msec')
 257     a = Time.now.to_f - 0.001
 258     status, header, bodies = cl.call(@req)
 259     assert_match %r(\A\d+\.\d{3}\n\z), str.string
 260     b = Time.now.to_f + 0.001
 261     logged = str.string.to_f
 262     assert logged >= a, "#{logged} >= #{a}"
 263     assert logged <= b, "#{logged} <= #{b}"
 264   end
 265
 266   def test_usec
 267     str = StringIO.new
 268     app = lambda { |env| [ 200, {}, [] ] }
 269     cl = Clogger.new(app, :logger => str, :format => '$usec')
 270     a = Time.now.to_f - 0.000001
 271     status, header, bodies = cl.call(@req)
 272     assert_match %r(\A\d+\.\d{6}\n\z), str.string
 273     b = Time.now.to_f + 0.000001
 274     logged = str.string.to_f
 275     assert logged >= a, "#{logged} >= #{a}"
 276     assert logged <= b, "#{logged} <= #{b}"
 277   end
 278
 279   def test_time_0
 280     str = StringIO.new
 281     app = lambda { |env| [ 200, {}, [] ] }
 282     cl = Clogger.new(app, :logger => str, :format => '$time{0}')
 283     a = Time.now.to_f - 1
 284     status, header, bodies = cl.call(@req)
 285     assert_match %r(\A\d+\n\z), str.string
 286     b = Time.now.to_f + 1
 287     logged = str.string.to_f
 288     assert logged >= a, "#{logged} >= #{a}"
 289     assert logged <= b, "#{logged} <= #{b}"
 290   end
 291
 292   def test_time_1
 293     str = StringIO.new
 294     app = lambda { |env| [ 200, {}, [] ] }
 295     cl = Clogger.new(app, :logger => str, :format => '$time{1}')
 296     a = Time.now.to_f - 0.5
 297     status, header, bodies = cl.call(@req)
 298     assert_match %r(\A\d+\.\d\n\z), str.string
 299     b = Time.now.to_f + 0.5
 300     logged = str.string.to_f
 301     assert logged >= a, "#{logged} >= #{a}"
 302     assert logged <= b, "#{logged} <= #{b}"
 303   end
 304
 305   def test_request_length
 306     str = StringIO.new
 307     input = StringIO.new('.....')
 308     app = lambda { |env| [ 200, {}, [] ] }
 309     cl = Clogger.new(app, :logger => str, :format => '$request_length')
 310     status, header, bodies = cl.call(@req.merge('rack.input' => input))
 311     assert_equal "5\n", str.string
 312   end
 313
 314   def test_response_length_0
 315     str = StringIO.new
 316     app = lambda { |env| [ 200, {}, [] ] }
 317     cl = Clogger.new(app, :logger => str, :format => '$response_length')
 318     status, header, bodies = cl.call(@req)
 319     bodies.each { |part| part }
 320     bodies.close
 321     assert_equal "-\n", str.string
 322   end
 323
 324   def test_combined
 325     start = DateTime.now - 1
 326     str = StringIO.new
 327     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
 328     cl = Clogger.new(app, :logger => str, :format => Combined)
 329     status, headers, body = cl.call(@req)
 330     tmp = []
 331     body.each { |s| tmp << s }
 332     body.close
 333     assert_equal %w(a b c), tmp
 334     str = str.string
 335     assert_match %r[" 200 3 "-" "echo and socat \\o/"\n\z], str
 336     tmp = nil
 337     %r{\[(\d+/\w+/\d+:\d+:\d+:\d+ .+)\]} =~ str
 338     assert $1
 339     assert_nothing_raised {
 340       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
 341     }
 342     assert tmp >= start
 343     assert tmp <= DateTime.now
 344   end
 345
 346   def test_rack_errors_fallback
 347     err = StringIO.new
 348     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
 349     cl = Clogger.new(app, :format => '$pid')
 350     req = @req.merge('rack.errors' => err)
 351     status, headers, body = cl.call(req)
 352     assert_equal "#$$\n", err.string
 353   end
 354
 355   def test_body_close
 356     s_body = StringIO.new(%w(a b c).join("\n"))
 357     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, s_body] }
 358     cl = Clogger.new(app, :logger => [], :format => '$pid')
 359     status, headers, body = cl.call(@req)
 360     assert ! s_body.closed?
 361     assert_nothing_raised { body.close }
 362     assert s_body.closed?
 363   end
 364
 365   def test_escape
 366     str = StringIO.new
 367     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, [] ] }
 368     cl = Clogger.new(app,
 369       :logger => str,
 370       :format => '$http_user_agent "$request"')
 371     bad = {
 372       'HTTP_USER_AGENT' => '"asdf"',
 373       'QUERY_STRING' => 'sdf=bar"',
 374       'PATH_INFO' => '/"<>"',
 375     }
 376     status, headers, body = cl.call(@req.merge(bad))
 377     expect = '\x22asdf\x22 "GET /\x22<>\x22?sdf=bar\x22 HTTP/1.0"' << "\n"
 378     assert_equal expect, str.string
 379   end
 380
 381   # rack allows repeated headers with "\n":
 382   # { 'Set-Cookie' => "a\nb" } =>
 383   #   Set-Cookie: a
 384   #   Set-Cookie: b
 385   def test_escape_header_newlines
 386     str = StringIO.new
 387     app = lambda { |env| [302, { 'Set-Cookie' => "a\nb" }, [] ] }
 388     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 389     cl.call(@req)
 390     assert_equal "a\\x0Ab\n", str.string
 391   end
 392
 393   def test_escape_crazy_delete
 394     str = StringIO.new
 395     app = lambda { |env| [302, {}, [] ] }
 396     cl = Clogger.new(app, :logger => str, :format => "$http_cookie")
 397     @req["HTTP_COOKIE"] = "a\x7f\xff"
 398     cl.call(@req)
 399     assert_equal "a\\x7F\\xFF\n", str.string
 400   end
 401
 402   def test_request_uri_fallback
 403     str = StringIO.new
 404     app = lambda { |env| [ 200, {}, [] ] }
 405     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 406     status, headers, body = cl.call(@req)
 407     assert_equal "/hello?goodbye=true\n", str.string
 408   end
 409
 410   def test_request_uri_set
 411     str = StringIO.new
 412     app = lambda { |env| [ 200, {}, [] ] }
 413     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 414     status, headers, body = cl.call(@req.merge("REQUEST_URI" => '/zzz'))
 415     assert_equal "/zzz\n", str.string
 416   end
 417
 418   def test_cookies
 419     str = StringIO.new
 420     app = lambda { |env|
 421       req = Rack::Request.new(env).cookies
 422       [ 302, {}, [] ]
 423     }
 424     cl = Clogger.new(app,
 425         :format => '$cookie_foo $cookie_quux',
 426         :logger => str)
 427     req = @req.merge('HTTP_COOKIE' => "foo=bar;quux=h%7F&m")
 428     status, headers, body = cl.call(req)
 429     assert_equal "bar h\\x7F&m\n", str.string
 430   end
 431
 432   def test_bogus_app_response
 433     str = StringIO.new
 434     app = lambda { |env| 302 }
 435     cl = Clogger.new(app, :logger => str)
 436     assert_raise(TypeError) { cl.call(@req) }
 437     str = str.string
 438     e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
 439     assert_match %r{#{e}$}m, str
 440   end
 441
 442   def test_broken_header_response
 443     str = StringIO.new
 444     app = lambda { |env| [302, [ %w(a) ], []] }
 445     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 446     assert_nothing_raised { cl.call(@req) }
 447   end
 448
 449   def test_subclass_hash
 450     str = StringIO.new
 451     req = Rack::Utils::HeaderHash.new(@req)
 452     app = lambda { |env| [302, [ %w(a) ], []] }
 453     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 454     assert_nothing_raised { cl.call(req).last.each {}.close }
 455     assert str.size > 0
 456   end
 457
 458   def test_subclassed_string_req
 459     str = StringIO.new
 460     req = {}
 461     @req.each { |key,value|
 462       req[FooString.new(key)] = value.kind_of?(String) ?
 463                                 FooString.new(value) : value
 464     }
 465     app = lambda { |env| [302, [ %w(a) ], []] }
 466     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 467     assert_nothing_raised { cl.call(req).last.each {}.close }
 468     assert str.size > 0
 469   end
 470
 471   def test_subclassed_string_in_body
 472     str = StringIO.new
 473     body = "hello"
 474     r = nil
 475     app = lambda { |env| [302, [ %w(a) ], [FooString.new(body)]] }
 476     cl = Clogger.new(app, :logger => str, :format => '$body_bytes_sent')
 477     assert_nothing_raised { cl.call(@req).last.each { |x| r = x }.close }
 478     assert str.size > 0
 479     assert_equal body.size.to_s << "\n", str.string
 480     assert_equal r, body
 481     assert r.object_id != body.object_id
 482   end
 483
 484   # Rack::BodyProxy does this thing with method_missing
 485   # This test fails under MRI 1.9.1 and 1.9.2, but works under 1.9.3
 486   def test_each_with_external_block
 487     foo = Object.new
 488     foo.instance_variable_set(:@body, ["BodyProxy"])
 489     def foo.method_missing(*args, &block)
 490       @body.__send__(*args, &block)
 491     end
 492     app = lambda { |env| [302, [], foo] }
 493     str = StringIO.new
 494     cl = Clogger.new(app, :logger => str, :format => '$body_bytes_sent')
 495     r = nil
 496     assert_nothing_raised { r = cl.call(@req) }
 497     body = []
 498     r[2].each { |x| body << x }
 499     r[2].close
 500     assert_equal %w(BodyProxy), body
 501     assert_equal "9\n", str.string
 502   end
 503
 504   def test_http_09_request
 505     str = StringIO.new
 506     app = lambda { |env| [302, [ %w(a) ], []] }
 507     cl = Clogger.new(app, :logger => str, :format => '$request')
 508     req = @req.dup
 509     req.delete 'HTTP_VERSION'
 510     cl.call(req)
 511     assert_equal "GET /hello?goodbye=true\n", str.string
 512   end
 513
 514   def test_request_method_only
 515     str = StringIO.new
 516     app = lambda { |env| [302, [ %w(a) ], []] }
 517     cl = Clogger.new(app, :logger => str, :format => '$request_method')
 518     cl.call(@req)
 519     assert_equal "GET\n", str.string
 520   end
 521
 522   def test_content_length_null
 523     str = StringIO.new
 524     app = lambda { |env| [302, [ %w(a) ], []] }
 525     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 526     cl.call(@req)
 527     assert_equal "-\n", str.string
 528   end
 529
 530   def test_content_length_set
 531     str = StringIO.new
 532     app = lambda { |env| [302, [ %w(a) ], []] }
 533     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 534     cl.call(@req.merge('CONTENT_LENGTH' => '5'))
 535     assert_equal "5\n", str.string
 536   end
 537
 538   def test_http_content_type_fallback
 539     str = StringIO.new
 540     app = lambda { |env| [302, [ %w(a) ], []] }
 541     cl = Clogger.new(app, :logger => str, :format => '$http_content_type')
 542     cl.call(@req.merge('CONTENT_TYPE' => 'text/plain'))
 543     assert_equal "text/plain\n", str.string
 544   end
 545
 546   def test_clogger_synced
 547     io = StringIO.new
 548     logger = Struct.new(:sync, :io).new(false, io)
 549     assert ! logger.sync
 550     def logger.<<(str)
 551       io << str
 552     end
 553     app = lambda { |env| [302, [ %w(a) ], []] }
 554     cl = Clogger.new(app, :logger => logger)
 555     assert logger.sync
 556   end
 557
 558   def test_clogger_unsyncable
 559     logger = ''
 560     assert ! logger.respond_to?('sync=')
 561     app = lambda { |env| [302, [ %w(a) ], []] }
 562     assert_nothing_raised { Clogger.new(app, :logger => logger) }
 563   end
 564
 565   def test_clogger_no_ORS
 566     s = ''
 567     app = lambda { |env| [302, [ %w(a) ], []] }
 568     cl = Clogger.new(app, :logger => s, :format => "$request", :ORS => "")
 569     cl.call(@req)
 570     assert_equal "GET /hello?goodbye=true HTTP/1.0", s
 571   end
 572
 573   def test_clogger_weird_ORS
 574     s = ''
 575     app = lambda { |env| [302, [ %w(a) ], []] }
 576     cl = Clogger.new(app, :logger => s, :format => "<$request", :ORS => ">")
 577     cl.call(@req)
 578     assert_equal "<GET /hello?goodbye=true HTTP/1.0>", s
 579   end
 580
 581   def test_clogger_body_not_closeable
 582     s = ''
 583     app = lambda { |env| [302, [ %w(a) ], []] }
 584     cl = Clogger.new(app, :logger => s)
 585     status, headers, body = cl.call(@req)
 586     assert_nil body.close
 587   end
 588
 589   def test_clogger_response_frozen
 590     response = [ 200, { "AAAA" => "AAAA"}.freeze, [].freeze ].freeze
 591     s = StringIO.new("")
 592     app = Rack::Builder.new do
 593       use Clogger, :logger => s, :format => "$request_time $http_host"
 594       run lambda { |env| response }
 595     end
 596     assert_nothing_raised do
 597       3.times do
 598         resp = app.call(@req)
 599         assert ! resp.frozen?
 600         resp.last.each { |x| }
 601       end
 602     end
 603   end
 604
 605   def test_clogger_body_close_return_value
 606     s = ''
 607     body = []
 608     def body.close
 609       :foo
 610     end
 611     app = lambda { |env| [302, [ %w(a) ], body ] }
 612     cl = Clogger.new(app, :logger => s)
 613     status, headers, body = cl.call(@req)
 614     assert_equal :foo, body.close
 615   end
 616
 617   def test_clogger_auto_reentrant_true
 618     s = ''
 619     body = []
 620     app = lambda { |env| [302, [ %w(a) ], body ] }
 621     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 622     @req['rack.multithread'] = true
 623     status, headers, body = cl.call(@req)
 624     assert cl.reentrant?
 625   end
 626
 627   def test_clogger_auto_reentrant_false
 628     s = ''
 629     body = []
 630     app = lambda { |env| [302, [ %w(a) ], body ] }
 631     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 632     @req['rack.multithread'] = false
 633     status, headers, body = cl.call(@req)
 634     assert ! cl.reentrant?
 635   end
 636
 637   def test_clogger_auto_reentrant_forced_true
 638     s = ''
 639     body = []
 640     app = lambda { |env| [302, [ %w(a) ], body ] }
 641     o = { :logger => s, :format => "$request_time", :reentrant => true }
 642     cl = Clogger.new(app, o)
 643     @req['rack.multithread'] = false
 644     status, headers, body = cl.call(@req)
 645     assert cl.reentrant?
 646   end
 647
 648   def test_clogger_auto_reentrant_forced_false
 649     s = ''
 650     body = []
 651     app = lambda { |env| [302, [ %w(a) ], body ] }
 652     o = { :logger => s, :format => "$request_time", :reentrant => false }
 653     cl = Clogger.new(app, o)
 654     @req['rack.multithread'] = true
 655     status, headers, body = cl.call(@req)
 656     assert ! cl.reentrant?
 657   end
 658
 659   def test_invalid_status
 660     s = []
 661     body = []
 662     app = lambda { |env| [ env["force.status"], [ %w(a b) ], body ] }
 663     o = { :logger => s, :format => "$status" }
 664     cl = Clogger.new(app, o)
 665     status, headers, body = cl.call(@req.merge("force.status" => -1))
 666     assert_equal -1, status
 667     assert_equal "-\n", s.last
 668     status, headers, body = cl.call(@req.merge("force.status" => 1000))
 669     assert_equal 1000, status
 670     assert_equal "-\n", s.last
 671     u64_max = 0xffffffffffffffff
 672     status, headers, body = cl.call(@req.merge("force.status" => u64_max))
 673     assert_equal u64_max, status
 674     assert_equal "-\n", s.last
 675   end
 676
 677   # so we don't  care about the portability of this test
 678   # if it doesn't leak on Linux, it won't leak anywhere else
 679   # unless your C compiler or platform is otherwise broken
 680   LINUX_PROC_PID_STATUS = "/proc/self/status"
 681   def test_memory_leak
 682     app = lambda { |env| [ 0, {}, [] ] }
 683     clogger = Clogger.new(app, :logger => $stderr)
 684     match_rss = /^VmRSS:\s+(\d+)/
 685     if File.read(LINUX_PROC_PID_STATUS) =~ match_rss
 686       before = $1.to_i
 687       1000000.times { clogger.dup }
 688       File.read(LINUX_PROC_PID_STATUS) =~ match_rss
 689       after = $1.to_i
 690       diff = after - before
 691       assert(diff < 10000, "memory grew more than 10M: #{diff}")
 692     end
 693   end if RUBY_PLATFORM =~ /linux/ && File.readable?(LINUX_PROC_PID_STATUS)
 694
 695   def test_path_open_file
 696     tmp = Tempfile.new('test_clogger')
 697     app = lambda { |env| [ 200, {}, [] ] }
 698     app = Clogger.new(app, :format => '$status', :path => tmp.path)
 699     assert_kind_of Integer, app.fileno
 700     assert app.fileno != tmp.fileno
 701     status, headers, body = app.call(@req)
 702     assert_equal "200\n", tmp.read
 703   end
 704
 705   def test_path_logger_conflict
 706     tmp = Tempfile.new('test_clogger')
 707     app = lambda { |env| [ 200, {}, [] ] }
 708     assert_raises(ArgumentError) {
 709       Clogger.new(app, :logger=> $stderr, :path => tmp.path)
 710     }
 711   end
 712
 713   def test_request_time
 714     s = []
 715     app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
 716     cl = Clogger.new(app, :logger => s, :format => "$request_time")
 717     status, headers, body = cl.call(@req)
 718     assert_nothing_raised { body.each { |x| } ; body.close }
 719     assert s[-1].to_f >= 0.100
 720     assert s[-1].to_f <= 0.110
 721   end
 722
 723   def test_insanely_long_time_format
 724     s = []
 725     app = lambda { |env| [200, [], [] ] }
 726     fmt = '%Y' * 100
 727     expect = Time.now.utc.strftime(fmt) << "\n"
 728     assert_equal 100 * 4 + 1, expect.size
 729     cl = Clogger.new(app, :logger => s, :format => "$time_utc{#{fmt}}")
 730     status, headers, body = cl.call(@req)
 731     assert_equal expect, s[0]
 732   end
 733
 734   def test_time_utc
 735     s = []
 736     app = lambda { |env| [200, [], [] ] }
 737     cl = Clogger.new(app, :logger => s, :format => "$time_utc")
 738     status, headers, body = cl.call(@req)
 739     assert %r!\A\d+/\w+/\d{4}:\d\d:\d\d:\d\d \+0000\n\z! =~ s[0], s.inspect
 740   end
 741
 742   def test_time_iso8601
 743     s = []
 744     app = lambda { |env| [200, [], [] ] }
 745     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 746     status, headers, body = cl.call(@req)
 747     t = Time.parse(s[0])
 748     assert_equal t.iso8601, s[0].strip
 749   end
 750
 751   def test_time_iso8601_pst8pdt
 752     ENV["TZ"] = "PST8PDT"
 753     s = []
 754     app = lambda { |env| [200, [], [] ] }
 755     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 756     status, headers, body = cl.call(@req)
 757     t = Time.parse(s[0])
 758     assert_equal t.iso8601, s[0].strip
 759   end
 760
 761   def test_time_iso8601_utc
 762     ENV["TZ"] = "UTC"
 763     s = []
 764     app = lambda { |env| [200, [], [] ] }
 765     cl = Clogger.new(app, :logger => s, :format => "$time_iso8601")
 766     status, headers, body = cl.call(@req)
 767     t = Time.parse(s[0])
 768     assert_equal t.iso8601, s[0].strip
 769   end
 770
 771   def test_time_local
 772     s = []
 773     app = lambda { |env| [200, [], [] ] }
 774     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 775     status, headers, body = cl.call(@req)
 776     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 777     assert_equal t.strftime(@nginx_fmt), s[0].strip
 778   end
 779
 780   def test_time_local_pst8pdt
 781     orig = ENV["TZ"]
 782     ENV["TZ"] = "PST8PDT"
 783     s = []
 784     app = lambda { |env| [200, [], [] ] }
 785     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 786     status, headers, body = cl.call(@req)
 787     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 788     assert_equal t.strftime(@nginx_fmt), s[0].strip
 789   end
 790
 791   def test_time_local_utc
 792     ENV["TZ"] = "UTC"
 793     s = []
 794     app = lambda { |env| [200, [], [] ] }
 795     cl = Clogger.new(app, :logger => s, :format => "$time_local")
 796     status, headers, body = cl.call(@req)
 797     t = DateTime.strptime(s[0].strip, @nginx_fmt)
 798     assert_equal t.strftime(@nginx_fmt), s[0].strip
 799   end
 800
 801   def test_method_missing
 802     s = []
 803     body = []
 804     def body.foo_bar(foo)
 805       [ foo.to_s ]
 806     end
 807     def body.noargs
 808       :hello
 809     end
 810     def body.omg(&block)
 811       yield :PONIES
 812     end
 813     app = lambda { |env| [200, [], body ] }
 814     cl = Clogger.new(app, :logger => s, :format => '$body_bytes_sent')
 815     status, headers, body = cl.call(@req)
 816     assert_nothing_raised do
 817       body.each { |x| s << x }
 818       body.close
 819     end
 820     assert_equal "0\n", s[0], s.inspect
 821     assert_kind_of Clogger, body
 822     assert_equal %w(1), body.foo_bar(1)
 823     assert_equal :hello, body.noargs
 824     body.omg { |x| s << x }
 825     assert_equal :PONIES, s[1]
 826     assert_equal 2, s.size
 827   end
 828
 829   def test_full_uri
 830     s = []
 831     format = '"$request_method ' \
 832              '$env{rack.url_scheme}://$http_host$request_uri $http_version"'
 833     app = lambda { |env| [200, [], [] ] }
 834     cl = Clogger.new(app, :logger => s, :format => format)
 835     @req["HTTP_HOST"] = "example.com"
 836     status, headers, body = cl.call(@req)
 837     expect = "\"GET http://example.com/hello?goodbye=true HTTP/1.0\"\n"
 838     assert_equal [ expect ], s
 839   end
 840
 841   def test_lint_error_wrapper
 842     require 'rack/lobster'
 843     @req["SERVER_NAME"] = "FOO"
 844     @req["SERVER_PORT"] = "666"
 845     @req["rack.version"] = [1,1]
 846     @req["rack.multithread"] = true
 847     @req["rack.multiprocess"] = true
 848     @req["rack.run_once"] = false
 849     app = Rack::ContentLength.new(Rack::ContentType.new(Rack::Lobster.new))
 850     cl = Clogger.new(app, :format => :Combined)
 851     @req["rack.errors"] = err = StringIO.new
 852     status, headers, body = r = Rack::Lint.new(cl).call(@req)
 853     body.each { |x| assert_kind_of String, x.to_str }
 854     body.close # might raise here
 855     assert_match(%r{GET /hello}, err.string)
 856   end
 857 end