test/test_clogger.rb

   1 # -*- encoding: binary -*-
   2 $stderr.sync = $stdout.sync = true
   3 require "test/unit"
   4 require "date"
   5 require "stringio"
   6
   7 require "rack"
   8
   9 require "clogger"
  10 class TestClogger < Test::Unit::TestCase
  11   include Clogger::Format
  12
  13   def setup
  14     @req = {
  15       "REQUEST_METHOD" => "GET",
  16       "HTTP_VERSION" => "HTTP/1.0",
  17       "HTTP_USER_AGENT" => 'echo and socat \o/',
  18       "PATH_INFO" => "/hello",
  19       "QUERY_STRING" => "goodbye=true",
  20       "rack.errors" => $stderr,
  21       "rack.input" => File.open('/dev/null', 'rb'),
  22       "REMOTE_ADDR" => 'home',
  23     }
  24   end
  25
  26   def test_init_basic
  27     Clogger.new(lambda { |env| [ 0, {}, [] ] })
  28   end
  29
  30   def test_init_noargs
  31     assert_raise(ArgumentError) { Clogger.new }
  32   end
  33
  34   def test_init_stderr
  35     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => $stderr)
  36     assert_kind_of(Integer, cl.fileno)
  37     assert_equal $stderr.fileno, cl.fileno
  38   end
  39
  40   def test_init_stringio
  41     cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => StringIO.new)
  42     assert_nil cl.fileno
  43   end
  44
  45   def test_write_stringio
  46     start = DateTime.now - 1
  47     str = StringIO.new
  48     cl = Clogger.new(lambda { |env| [ "302 Found", {}, [] ] }, :logger => str)
  49     status, headers, body = cl.call(@req)
  50     assert_equal("302 Found", status)
  51     assert_equal({}, headers)
  52     body.each { |part| assert false }
  53     str = str.string
  54     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 302 -\n\z}
  55     assert_match r, str
  56     %r{\[([^\]]+)\]} =~ str
  57     tmp = nil
  58     assert_nothing_raised {
  59       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
  60     }
  61     assert tmp >= start
  62     assert tmp <= DateTime.now
  63   end
  64
  65   def test_clen_stringio
  66     start = DateTime.now - 1
  67     str = StringIO.new
  68     app = lambda { |env| [ 301, {'Content-Length' => '5'}, ['abcde'] ] }
  69     format = Common.dup
  70     assert format.gsub!(/response_length/, 'sent_http_content_length')
  71     cl = Clogger.new(app, :logger => str, :format => format)
  72     status, headers, body = cl.call(@req)
  73     assert_equal(301, status)
  74     assert_equal({'Content-Length' => '5'}, headers)
  75     body.each { |part| assert_equal('abcde', part) }
  76     str = str.string
  77     r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 301 5\n\z}
  78     assert_match r, str
  79     %r{\[([^\]]+)\]} =~ str
  80     tmp = nil
  81     assert_nothing_raised {
  82       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
  83     }
  84     assert tmp >= start
  85     assert tmp <= DateTime.now
  86   end
  87
  88   def test_compile_ambiguous
  89     cl = Clogger.new(nil, :logger => $stderr)
  90     ary = nil
  91     cl.instance_eval {
  92       ary = compile_format(
  93         '$remote_addr $$$$pid' \
  94         "\n")
  95     }
  96     expect = [
  97       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
  98       [ Clogger::OP_LITERAL, " " ],
  99       [ Clogger::OP_LITERAL, "$$$" ],
 100       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:pid] ],
 101       [ Clogger::OP_LITERAL, "\n" ],
 102       ]
 103     assert_equal expect, ary
 104   end
 105
 106   def test_compile_auto_newline
 107     cl = Clogger.new(nil, :logger => $stderr)
 108     ary = nil
 109     cl.instance_eval { ary = compile_format('$remote_addr $request') }
 110     expect = [
 111       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 112       [ Clogger::OP_LITERAL, " " ],
 113       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
 114       [ Clogger::OP_LITERAL, "\n" ],
 115       ]
 116     assert_equal expect, ary
 117   end
 118
 119   def test_big_log
 120     str = StringIO.new
 121     fmt = '$remote_addr $pid $remote_user [$time_local] ' \
 122           '"$request" $status $body_bytes_sent "$http_referer" ' \
 123          '"$http_user_agent" "$http_cookie" $request_time $http_host'
 124     app = lambda { |env| [ 302, {}, [] ] }
 125     cl = Clogger.new(app, :logger => str, :format => fmt)
 126     cookie = "foo=bar#{'f' * 256}".freeze
 127     req = {
 128       'HTTP_HOST' => 'example.com:12345',
 129       'HTTP_COOKIE' => cookie,
 130     }
 131     req = @req.merge(req)
 132     cl.call(req).last.each { |part| part }
 133     str = str.string
 134     assert(str.size > 128)
 135     assert_match %r["echo and socat \\o/" "#{cookie}" \d+\.\d{3}], str
 136     assert_match %r["#{cookie}" \d+\.\d{3} example\.com:12345\n\z], str
 137   end
 138
 139   def test_compile
 140     cl = Clogger.new(nil, :logger => $stderr)
 141     ary = nil
 142     cl.instance_eval {
 143       ary = compile_format(
 144         '$remote_addr - $remote_user [$time_local] ' \
 145         '"$request" $status $body_bytes_sent "$http_referer" ' \
 146         '"$http_user_agent" "$http_cookie" $request_time ' \
 147         '$env{rack.url_scheme}' \
 148         "\n")
 149     }
 150     expect = [
 151       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
 152       [ Clogger::OP_LITERAL, " - " ],
 153       [ Clogger::OP_REQUEST, "REMOTE_USER" ],
 154       [ Clogger::OP_LITERAL, " [" ],
 155       [ Clogger::OP_TIME_LOCAL, '%d/%b/%Y:%H:%M:%S %z' ],
 156       [ Clogger::OP_LITERAL, "] \"" ],
 157       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
 158       [ Clogger::OP_LITERAL, "\" "],
 159       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:status] ],
 160       [ Clogger::OP_LITERAL, " "],
 161       [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:body_bytes_sent] ],
 162       [ Clogger::OP_LITERAL, " \"" ],
 163       [ Clogger::OP_REQUEST, "HTTP_REFERER" ],
 164       [ Clogger::OP_LITERAL, "\" \"" ],
 165       [ Clogger::OP_REQUEST, "HTTP_USER_AGENT" ],
 166       [ Clogger::OP_LITERAL, "\" \"" ],
 167       [ Clogger::OP_REQUEST, "HTTP_COOKIE" ],
 168       [ Clogger::OP_LITERAL, "\" " ],
 169       [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000 ],
 170       [ Clogger::OP_LITERAL, " " ],
 171       [ Clogger::OP_REQUEST, "rack.url_scheme" ],
 172       [ Clogger::OP_LITERAL, "\n" ],
 173     ]
 174     assert_equal expect, ary
 175   end
 176
 177   def test_eval
 178     current = Thread.current.to_s
 179     str = StringIO.new
 180     app = lambda { |env| [ 302, {}, [] ] }
 181     cl = Clogger.new(app,
 182                     :logger => str,
 183                     :format => "-$e{Thread.current}-\n")
 184     status, headers, body = cl.call(@req)
 185     assert_equal "-#{current}-\n", str.string
 186   end
 187
 188   def test_pid
 189     str = StringIO.new
 190     app = lambda { |env| [ 302, {}, [] ] }
 191     cl = Clogger.new(app, :logger => str, :format => "[$pid]\n")
 192     status, headers, body = cl.call(@req)
 193     assert_equal "[#$$]\n", str.string
 194   end
 195
 196   def test_rack_xff
 197     str = StringIO.new
 198     app = lambda { |env| [ 302, {}, [] ] }
 199     cl = Clogger.new(app, :logger => str, :format => "$ip")
 200     req = @req.merge("HTTP_X_FORWARDED_FOR" => '192.168.1.1')
 201     status, headers, body = cl.call(req)
 202     assert_equal "192.168.1.1\n", str.string
 203     str.rewind
 204     str.truncate(0)
 205     status, headers, body = cl.call(@req)
 206     assert_equal "home\n", str.string
 207     str.rewind
 208     str.truncate(0)
 209   end
 210
 211   def test_rack_1_0
 212     start = DateTime.now - 1
 213     str = StringIO.new
 214     app = lambda { |env| [ 200, {'Content-Length'=>'0'}, %w(a b c)] }
 215     cl = Clogger.new(app, :logger => str, :format => Rack_1_0)
 216     status, headers, body = cl.call(@req)
 217     tmp = []
 218     body.each { |s| tmp << s }
 219     assert_equal %w(a b c), tmp
 220     str = str.string
 221     assert_match %r[" 200 3 \d+\.\d{4}\n\z], str
 222     tmp = nil
 223     %r{\[(\d+/\w+/\d+ \d+:\d+:\d+)\]} =~ str
 224     assert $1
 225     assert_nothing_raised { tmp = DateTime.strptime($1, "%d/%b/%Y %H:%M:%S") }
 226     assert tmp >= start
 227     assert tmp <= DateTime.now
 228   end
 229
 230   def test_msec
 231     str = StringIO.new
 232     app = lambda { |env| [ 200, {}, [] ] }
 233     cl = Clogger.new(app, :logger => str, :format => '$msec')
 234     status, header, bodies = cl.call(@req)
 235     assert_match %r(\A\d+\.\d{3}\n\z), str.string
 236   end
 237
 238   def test_usec
 239     str = StringIO.new
 240     app = lambda { |env| [ 200, {}, [] ] }
 241     cl = Clogger.new(app, :logger => str, :format => '$usec')
 242     status, header, bodies = cl.call(@req)
 243     assert_match %r(\A\d+\.\d{6}\n\z), str.string
 244   end
 245
 246   def test_time_0
 247     str = StringIO.new
 248     app = lambda { |env| [ 200, {}, [] ] }
 249     cl = Clogger.new(app, :logger => str, :format => '$time{0}')
 250     status, header, bodies = cl.call(@req)
 251     assert_match %r(\A\d+\n\z), str.string
 252   end
 253
 254   def test_time_1
 255     str = StringIO.new
 256     app = lambda { |env| [ 200, {}, [] ] }
 257     cl = Clogger.new(app, :logger => str, :format => '$time{1}')
 258     status, header, bodies = cl.call(@req)
 259     assert_match %r(\A\d+\.\d\n\z), str.string
 260   end
 261
 262   def test_request_length
 263     str = StringIO.new
 264     input = StringIO.new('.....')
 265     app = lambda { |env| [ 200, {}, [] ] }
 266     cl = Clogger.new(app, :logger => str, :format => '$request_length')
 267     status, header, bodies = cl.call(@req.merge('rack.input' => input))
 268     assert_equal "5\n", str.string
 269   end
 270
 271   def test_response_length_0
 272     str = StringIO.new
 273     app = lambda { |env| [ 200, {}, [] ] }
 274     cl = Clogger.new(app, :logger => str, :format => '$response_length')
 275     status, header, bodies = cl.call(@req)
 276     bodies.each { |part| part }
 277     assert_equal "-\n", str.string
 278   end
 279
 280   def test_combined
 281     start = DateTime.now - 1
 282     str = StringIO.new
 283     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
 284     cl = Clogger.new(app, :logger => str, :format => Combined)
 285     status, headers, body = cl.call(@req)
 286     tmp = []
 287     body.each { |s| tmp << s }
 288     assert_equal %w(a b c), tmp
 289     str = str.string
 290     assert_match %r[" 200 3 "-" "echo and socat \\o/"\n\z], str
 291     tmp = nil
 292     %r{\[(\d+/\w+/\d+:\d+:\d+:\d+ .+)\]} =~ str
 293     assert $1
 294     assert_nothing_raised {
 295       tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
 296     }
 297     assert tmp >= start
 298     assert tmp <= DateTime.now
 299   end
 300
 301   def test_rack_errors_fallback
 302     err = StringIO.new
 303     app = lambda { |env| [ 200, {'Content-Length'=>'3'}, %w(a b c)] }
 304     cl = Clogger.new(app, :format => '$pid')
 305     req = @req.merge('rack.errors' => err)
 306     status, headers, body = cl.call(req)
 307     assert_equal "#$$\n", err.string
 308   end
 309
 310   def test_body_close
 311     s_body = StringIO.new(%w(a b c).join("\n"))
 312     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, s_body] }
 313     cl = Clogger.new(app, :logger => [], :format => '$pid')
 314     status, headers, body = cl.call(@req)
 315     assert ! s_body.closed?
 316     assert_nothing_raised { body.close }
 317     assert s_body.closed?
 318   end
 319
 320   def test_escape
 321     str = StringIO.new
 322     app = lambda { |env| [ 200, {'Content-Length'=>'5'}, [] ] }
 323     cl = Clogger.new(app,
 324       :logger => str,
 325       :format => '$http_user_agent "$request"')
 326     bad = {
 327       'HTTP_USER_AGENT' => '"asdf"',
 328       'QUERY_STRING' => 'sdf=bar"',
 329       'PATH_INFO' => '/"<>"',
 330     }
 331     status, headers, body = cl.call(@req.merge(bad))
 332     expect = '\x22asdf\x22 "GET /\x22<>\x22?sdf=bar\x22 HTTP/1.0"' << "\n"
 333     assert_equal expect, str.string
 334   end
 335
 336   # rack allows repeated headers with "\n":
 337   # { 'Set-Cookie' => "a\nb" } =>
 338   #   Set-Cookie: a
 339   #   Set-Cookie: b
 340   def test_escape_header_newlines
 341     str = StringIO.new
 342     app = lambda { |env| [302, { 'Set-Cookie' => "a\nb" }, [] ] }
 343     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 344     cl.call(@req)
 345     assert_equal "a\\x0Ab\n", str.string
 346   end
 347
 348   def test_request_uri_fallback
 349     str = StringIO.new
 350     app = lambda { |env| [ 200, {}, [] ] }
 351     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 352     status, headers, body = cl.call(@req)
 353     assert_equal "/hello?goodbye=true\n", str.string
 354   end
 355
 356   def test_request_uri_set
 357     str = StringIO.new
 358     app = lambda { |env| [ 200, {}, [] ] }
 359     cl = Clogger.new(app, :logger => str, :format => '$request_uri')
 360     status, headers, body = cl.call(@req.merge("REQUEST_URI" => '/zzz'))
 361     assert_equal "/zzz\n", str.string
 362   end
 363
 364   def test_cookies
 365     str = StringIO.new
 366     app = lambda { |env|
 367       req = Rack::Request.new(env).cookies
 368       [ 302, {}, [] ]
 369     }
 370     cl = Clogger.new(app,
 371         :format => '$cookie_foo $cookie_quux',
 372         :logger => str)
 373     req = @req.merge('HTTP_COOKIE' => "foo=bar;quux=h&m")
 374     status, headers, body = cl.call(req)
 375     assert_equal "bar h&m\n", str.string
 376   end
 377
 378   def test_bogus_app_response
 379     str = StringIO.new
 380     app = lambda { |env| 302 }
 381     cl = Clogger.new(app, :logger => str)
 382     assert_raise(TypeError) { cl.call(@req) }
 383     str = str.string
 384     e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
 385     assert_match %r{#{e}$}m, str
 386   end
 387
 388   def test_broken_header_response
 389     str = StringIO.new
 390     app = lambda { |env| [302, [ %w(a) ], []] }
 391     cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
 392     assert_raise(TypeError) { cl.call(@req) }
 393   end
 394
 395   def test_http_09_request
 396     str = StringIO.new
 397     app = lambda { |env| [302, [ %w(a) ], []] }
 398     cl = Clogger.new(app, :logger => str, :format => '$request')
 399     req = @req.dup
 400     req.delete 'HTTP_VERSION'
 401     cl.call(req)
 402     assert_equal "GET /hello?goodbye=true\n", str.string
 403   end
 404
 405   def test_request_method_only
 406     str = StringIO.new
 407     app = lambda { |env| [302, [ %w(a) ], []] }
 408     cl = Clogger.new(app, :logger => str, :format => '$request_method')
 409     cl.call(@req)
 410     assert_equal "GET\n", str.string
 411   end
 412
 413   def test_content_length_null
 414     str = StringIO.new
 415     app = lambda { |env| [302, [ %w(a) ], []] }
 416     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 417     cl.call(@req)
 418     assert_equal "-\n", str.string
 419   end
 420
 421   def test_content_length_set
 422     str = StringIO.new
 423     app = lambda { |env| [302, [ %w(a) ], []] }
 424     cl = Clogger.new(app, :logger => str, :format => '$content_length')
 425     cl.call(@req.merge('CONTENT_LENGTH' => '5'))
 426     assert_equal "5\n", str.string
 427   end
 428
 429   def test_http_content_type_fallback
 430     str = StringIO.new
 431     app = lambda { |env| [302, [ %w(a) ], []] }
 432     cl = Clogger.new(app, :logger => str, :format => '$http_content_type')
 433     cl.call(@req.merge('CONTENT_TYPE' => 'text/plain'))
 434     assert_equal "text/plain\n", str.string
 435   end
 436
 437 end