about summary refs log tree commit homepage
diff options
context:
space:
mode:
authorEric Wong <e@80x24.org>2015-02-27 22:29:49 +0000
committerEric Wong <e@80x24.org>2015-02-27 22:29:49 +0000
commit5aea6f54743a6dd6cd58a2a1660d36f112190a9b (patch)
treee83882677ee665d1b204633b52a7eb89b380af0f
parent6f826c29bf10e6375ccd620928ddedd8292db839 (diff)
For users unable to compile the C extension, multithreaded usage
of clogger could return invalid request time measurements.

This does not affect users of the C extension.
-rw-r--r--lib/clogger/pure.rb17
1 files changed, 9 insertions, 8 deletions
diff --git a/lib/clogger/pure.rb b/lib/clogger/pure.rb
index bb3fc16..9efb00c 100644
--- a/lib/clogger/pure.rb
+++ b/lib/clogger/pure.rb
@@ -6,7 +6,7 @@
 class Clogger
 
   attr_accessor :env, :status, :headers, :body
-  attr_writer :body_bytes_sent
+  attr_writer :body_bytes_sent, :start
 
   def initialize(app, opts = {})
     # trigger autoload to avoid thread-safety issues later on
@@ -28,10 +28,10 @@ class Clogger
   end
 
   def call(env)
-    @start = Time.now
+    start = Time.now
     resp = @app.call(env)
     unless resp.instance_of?(Array) && resp.size == 3
-      log(env, 500, {})
+      log(env, 500, {}, start)
       raise TypeError, "app response not a 3 element Array: #{resp.inspect}"
     end
     status, headers, body = resp
@@ -39,13 +39,14 @@ class Clogger
     if @wrap_body
       @reentrant = env['rack.multithread'] if @reentrant.nil?
       wbody = @reentrant ? self.dup : self
+      wbody.start = start
       wbody.env = env
       wbody.status = status
       wbody.headers = headers
       wbody.body = body
       return [ status, headers, wbody ]
     end
-    log(env, status, headers)
+    log(env, status, headers, start)
     [ status, headers, body ]
   end
 
@@ -60,8 +61,8 @@ class Clogger
 
   def close
     @body.close if @body.respond_to?(:close)
-    ensure
-      log(@env, @status, @headers)
+  ensure
+    log(@env, @status, @headers)
   end
 
   def reentrant?
@@ -153,7 +154,7 @@ private
     format % [ sec, usec / div ]
   end
 
-  def log(env, status, headers)
+  def log(env, status, headers, start = @start)
     str = @fmt_ops.map { |op|
       case op[0]
       when OP_LITERAL; op[1]
@@ -164,7 +165,7 @@ private
       when OP_TIME_LOCAL; Time.now.strftime(op[1])
       when OP_TIME_UTC; Time.now.utc.strftime(op[1])
       when OP_REQUEST_TIME
-        t = Time.now - @start
+        t = Time.now - start
         time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2])
       when OP_TIME
         t = Time.now