1 # -*- encoding: binary -*-
2 $stderr.sync = $stdout.sync = true
10 class TestClogger < Test::Unit::TestCase
11 include Clogger::Format
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',
27 Clogger.new(lambda { |env| [ 0, {}, [] ] })
31 assert_raise(ArgumentError) { Clogger.new }
35 cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => $stderr)
36 assert_kind_of(Integer, cl.fileno)
37 assert_equal $stderr.fileno, cl.fileno
40 def test_init_stringio
41 cl = Clogger.new(lambda { |env| [ 0, {}, [] ] }, :logger => StringIO.new)
45 def test_write_stringio
46 start = DateTime.now - 1
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 }
54 r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 302 -\n\z}
56 %r{\[([^\]]+)\]} =~ str
58 assert_nothing_raised {
59 tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
62 assert tmp <= DateTime.now
65 def test_clen_stringio
66 start = DateTime.now - 1
68 app = lambda { |env| [ 301, {'Content-Length' => '5'}, ['abcde'] ] }
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) }
77 r = %r{\Ahome - - \[[^\]]+\] "GET /hello\?goodbye=true HTTP/1.0" 301 5\n\z}
79 %r{\[([^\]]+)\]} =~ str
81 assert_nothing_raised {
82 tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
85 assert tmp <= DateTime.now
88 def test_compile_ambiguous
89 cl = Clogger.new(nil, :logger => $stderr)
93 '$remote_addr $$$$pid' \
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" ],
103 assert_equal expect, ary
106 def test_compile_auto_newline
107 cl = Clogger.new(nil, :logger => $stderr)
109 cl.instance_eval { ary = compile_format('$remote_addr $request') }
111 [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
112 [ Clogger::OP_LITERAL, " " ],
113 [ Clogger::OP_SPECIAL, Clogger::SPECIAL_VARS[:request] ],
114 [ Clogger::OP_LITERAL, "\n" ],
116 assert_equal expect, ary
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
128 'HTTP_HOST' => 'example.com:12345',
129 'HTTP_COOKIE' => cookie,
131 req = @req.merge(req)
132 cl.call(req).last.each { |part| part }
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
140 cl = Clogger.new(nil, :logger => $stderr)
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}' \
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" ],
174 assert_equal expect, ary
178 current = Thread.current.to_s
180 app = lambda { |env| [ 302, {}, [] ] }
181 cl = Clogger.new(app,
183 :format => "-$e{Thread.current}-\n")
184 status, headers, body = cl.call(@req)
185 assert_equal "-#{current}-\n", str.string
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
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
205 status, headers, body = cl.call(@req)
206 assert_equal "home\n", str.string
212 start = DateTime.now - 1
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)
218 body.each { |s| tmp << s }
219 assert_equal %w(a b c), tmp
221 assert_match %r[" 200 3 \d+\.\d{4}\n\z], str
223 %r{\[(\d+/\w+/\d+ \d+:\d+:\d+)\]} =~ str
225 assert_nothing_raised { tmp = DateTime.strptime($1, "%d/%b/%Y %H:%M:%S") }
227 assert tmp <= DateTime.now
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
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
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
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
262 def test_request_length
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
271 def test_response_length_0
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
281 start = DateTime.now - 1
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)
287 body.each { |s| tmp << s }
288 assert_equal %w(a b c), tmp
290 assert_match %r[" 200 3 "-" "echo and socat \\o/"\n\z], str
292 %r{\[(\d+/\w+/\d+:\d+:\d+:\d+ .+)\]} =~ str
294 assert_nothing_raised {
295 tmp = DateTime.strptime($1, "%d/%b/%Y:%H:%M:%S %z")
298 assert tmp <= DateTime.now
301 def test_rack_errors_fallback
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
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?
322 app = lambda { |env| [ 200, {'Content-Length'=>'5'}, [] ] }
323 cl = Clogger.new(app,
325 :format => '$http_user_agent "$request"')
327 'HTTP_USER_AGENT' => '"asdf"',
328 'QUERY_STRING' => 'sdf=bar"',
329 'PATH_INFO' => '/"<>"',
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
336 # rack allows repeated headers with "\n":
337 # { 'Set-Cookie' => "a\nb" } =>
340 def test_escape_header_newlines
342 app = lambda { |env| [302, { 'Set-Cookie' => "a\nb" }, [] ] }
343 cl = Clogger.new(app, :logger => str, :format => '$sent_http_set_cookie')
345 assert_equal "a\\x0Ab\n", str.string
348 def test_request_uri_fallback
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
356 def test_request_uri_set
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
367 req = Rack::Request.new(env).cookies
370 cl = Clogger.new(app,
371 :format => '$cookie_foo $cookie_quux',
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
378 def test_bogus_app_response
380 app = lambda { |env| 302 }
381 cl = Clogger.new(app, :logger => str)
382 assert_raise(TypeError) { cl.call(@req) }
384 e = Regexp.quote " \"GET /hello?goodbye=true HTTP/1.0\" 500 -"
385 assert_match %r{#{e}$}m, str
388 def test_broken_header_response
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) }