Re: Downsizing CommonLogger

[Eric Wong <normalperson@yhbt.net>]

Eric Wong <normalperson@yhbt.net> wrote:
> Christian Neukirchen <chneukirchen@gmail.com> wrote:
> > Joshua Peek <josh@joshpeek.com> writes:
> > 
> > > I'll pull it in soon.
> > 
> > Does it log the right size for chunked outputs?  In logfiles, I want those...
> 
> I'm very late to the party, but no, it doesn't.
> 
> This also miscalculates request time if the body is being generated
> dynamically during #each.

I'd rather revert the original patch here for simplicity.

But if the original _dup was too much overhead maybe we can reach a
middle ground and only fall back to wrapping #each iff there's no
Content-Length header to be found.

I don't can't find any real applications to benchmark with; but the
following patch may be considered (try Content-Length first, fallback to
wrapping body#each):

diff --git a/lib/rack/commonlogger.rb b/lib/rack/commonlogger.rb
index 880f0fb..0316014 100644
--- a/lib/rack/commonlogger.rb
+++ b/lib/rack/commonlogger.rb
@@ -8,25 +8,8 @@ module Rack
     #             %{%s - %s [%s] "%s %s%s %s" %d %s\n} %
     FORMAT = %{%s - %s [%s] "%s %s%s %s" %d %s %0.4f\n}
 
-    def initialize(app, logger=nil)
-      @app = app
-      @logger = logger
-    end
-
-    def call(env)
-      began_at = Time.now
-      status, header, body = @app.call(env)
-      log(env, status, header, began_at)
-      [status, header, body]
-    end
-
-    private
-
-    def log(env, status, header, began_at)
+    def self.log(logger, env, status, began_at, length)
       now = Time.now
-      length = extract_content_length(header)
-
-      logger = @logger || env['rack.errors']
       logger.write FORMAT % [
         env['HTTP_X_FORWARDED_FOR'] || env["REMOTE_ADDR"] || "-",
         env["REMOTE_USER"] || "-",
@@ -40,13 +23,55 @@ module Rack
         now - began_at ]
     end
 
+    def initialize(app, logger=nil)
+      @app = app
+      @logger = logger
+    end
+
+    def call(env)
+      began_at = Time.now
+      status, header, body = @app.call(env)
+      logger = @logger || env['rack.errors']
+
+      if length = extract_content_length(header)
+        self.class.log(logger, env, status, began_at, length)
+      else
+        body = BodyWrapper.new(body, [ logger, env, status, began_at ])
+      end
+
+      [ status, header, body ]
+    end
+
+  private
+
     def extract_content_length(headers)
       headers.each do |key, value|
         if key.downcase == 'content-length'
           return value.to_s == '0' ? '-' : value
         end
       end
-      '-'
+      nil
     end
+
+    class BodyWrapper
+
+      def initialize(body, log_params)
+        @body = body
+        @log_params = log_params
+      end
+
+      def each
+        length = 0
+        @body.each { |part|
+          length += Rack::Utils.bytesize(part)
+          yield part
+        }
+        ensure
+          @log_params << length
+          CommonLogger.log(*@log_params)
+      end
+
+    end
+
   end
 end
diff --git a/test/spec_rack_commonlogger.rb b/test/spec_rack_commonlogger.rb
index 46a72e8..2b6bcf1 100644
--- a/test/spec_rack_commonlogger.rb
+++ b/test/spec_rack_commonlogger.rb
@@ -6,6 +6,13 @@ require 'rack/lobster'
 require 'rack/mock'
 
 context "Rack::CommonLogger" do
+  app_without_length_body = Object.new
+  def app_without_length_body.each
+    [ "5\r\nhello\r\n", "5\r\nworld\r\n", "0\r\n" ].each { |part|
+      yield part
+    }
+  end
+
   app = lambda { |env|
     [200,
      {"Content-Type" => "text/html", "Content-Length" => length.to_s},
@@ -13,7 +20,7 @@ context "Rack::CommonLogger" do
   app_without_length = lambda { |env|
     [200,
      {"Content-Type" => "text/html"},
-     []]}
+     app_without_length_body]}
   app_with_zero_length = lambda { |env|
     [200,
      {"Content-Type" => "text/html", "Content-Length" => "0"},
@@ -33,11 +40,11 @@ context "Rack::CommonLogger" do
     log.string.should =~ /"GET \/ " 200 #{length} /
   end
 
-  specify "should log - content length if header is missing" do
+  specify "should log correct content length if header is missing" do
     res = Rack::MockRequest.new(Rack::CommonLogger.new(app_without_length)).get("/")
 
     res.errors.should.not.be.empty
-    res.errors.should =~ /"GET \/ " 200 - /
+    res.errors.should =~ /"GET \/ " 200 23 /
   end
 
   specify "should log - content length if header is zero" do
-- 
Eric Wong