Downsizing CommonLogger

Downsizing CommonLogger

[Jeremy Kemper]

CommonLogger calculates the content length itself. This duplicates
work done by the app or ContentLength middleware.

The middleware is simpler, faster, and generates less garbage per
request by using the Content-Length header instead.

Patch: http://github.com/jeremy/rack/commit/f9d38d9d866060be39192675adcc2efc19164c6f

Best,
jeremy

Re: Downsizing CommonLogger

[Michael Fellinger]

On Wed, 29 Apr 2009 08:03:09 -0700
Jeremy Kemper <jeremy@bitsweat.net> wrote:

> CommonLogger calculates the content length itself. This duplicates
> work done by the app or ContentLength middleware.
> 
> The middleware is simpler, faster, and generates less garbage per
> request by using the Content-Length header instead.
> 
> Patch:
> http://github.com/jeremy/rack/commit/f9d38d9d866060be39192675adcc2efc19164c6f
> 
> Best,
> jeremy

+1
I've also long wanted to extract the format string like you did... so +2 actually :)

-- 
^ manveru

Re: Downsizing CommonLogger

[Jeremy Kemper]

On Wed, Apr 29, 2009 at 8:21 AM, Michael Fellinger
<m.fellinger@gmail.com> wrote:
>
> On Wed, 29 Apr 2009 08:03:09 -0700
> Jeremy Kemper <jeremy@bitsweat.net> wrote:
>
>> CommonLogger calculates the content length itself. This duplicates
>> work done by the app or ContentLength middleware.
>>
>> The middleware is simpler, faster, and generates less garbage per
>> request by using the Content-Length header instead.
>>
>> Patch:
>> http://github.com/jeremy/rack/commit/f9d38d9d866060be39192675adcc2efc19164c6f
>>
>> Best,
>> jeremy
>
> +1
> I've also long wanted to extract the format string like you did... so +2 actually :)
>
> --
> ^ manveru
>

This change is still on deck. Attention upstream :)

jeremy

Re: Downsizing CommonLogger

[Matt Todd]

[-- Attachment #1: Type: text/plain, Size: 1008 bytes --]

+1

On Wed, May 13, 2009 at 9:52 PM, Jeremy Kemper <jeremy@bitsweat.net> wrote:

>
> On Wed, Apr 29, 2009 at 8:21 AM, Michael Fellinger
> <m.fellinger@gmail.com> wrote:
> >
> > On Wed, 29 Apr 2009 08:03:09 -0700
> > Jeremy Kemper <jeremy@bitsweat.net> wrote:
> >
> >> CommonLogger calculates the content length itself. This duplicates
> >> work done by the app or ContentLength middleware.
> >>
> >> The middleware is simpler, faster, and generates less garbage per
> >> request by using the Content-Length header instead.
> >>
> >> Patch:
> >>
> http://github.com/jeremy/rack/commit/f9d38d9d866060be39192675adcc2efc19164c6f
> >>
> >> Best,
> >> jeremy
> >
> > +1
> > I've also long wanted to extract the format string like you did... so +2
> actually :)
> >
> > --
> > ^ manveru
> >
>
> This change is still on deck. Attention upstream :)
>
> jeremy
>



-- 
Matt Todd
Highgroove Studios
www.highgroove.com
cell: 404-314-2612
blog: maraby.org

Scout - Web Monitoring and Reporting Software
www.scoutapp.com

[-- Attachment #2: Type: text/html, Size: 1861 bytes --]

Re: Downsizing CommonLogger

[Joshua Peek]

+1

I'll pull it in soon.

On Thu, May 14, 2009 at 12:14 AM, Matt Todd <chiology@gmail.com> wrote:
> +1
>
> On Wed, May 13, 2009 at 9:52 PM, Jeremy Kemper <jeremy@bitsweat.net> wrote:
>>
>> On Wed, Apr 29, 2009 at 8:21 AM, Michael Fellinger
>> <m.fellinger@gmail.com> wrote:
>> >
>> > On Wed, 29 Apr 2009 08:03:09 -0700
>> > Jeremy Kemper <jeremy@bitsweat.net> wrote:
>> >
>> >> CommonLogger calculates the content length itself. This duplicates
>> >> work done by the app or ContentLength middleware.
>> >>
>> >> The middleware is simpler, faster, and generates less garbage per
>> >> request by using the Content-Length header instead.
>> >>
>> >> Patch:
>> >>
>> >> http://github.com/jeremy/rack/commit/f9d38d9d866060be39192675adcc2efc19164c6f
>> >>
>> >> Best,
>> >> jeremy
>> >
>> > +1
>> > I've also long wanted to extract the format string like you did... so +2
>> > actually :)
>> >
>> > --
>> > ^ manveru
>> >
>>
>> This change is still on deck. Attention upstream :)
>>
>> jeremy
>
>
>
> --
> Matt Todd
> Highgroove Studios
> www.highgroove.com
> cell: 404-314-2612
> blog: maraby.org
>
> Scout - Web Monitoring and Reporting Software
> www.scoutapp.com
>



-- 
Joshua Peek

Re: Downsizing CommonLogger

[Christian Neukirchen]

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...

-- 
Christian Neukirchen  <chneukirchen@gmail.com>  http://chneukirchen.org

Re: Downsizing CommonLogger

[Eric Wong]

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.

-- 
Eric Wong

Re: Downsizing CommonLogger

[Eric Wong]

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

Re: Downsizing CommonLogger

[Jeremy Kemper]

On Tue, Aug 11, 2009 at 9:38 PM, Eric Wong<normalperson@yhbt.net> wrote:
>
> 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):

Hey Eric,

Nice patch, but these changes were intentional. CommonLogger's concern
is logging the request, not calculating content length edge cases or
acting as a benchmarker. I'd advocate removing the timing entirely;
it's not part of the Common Log Format.

Best,
jeremy

Re: Downsizing CommonLogger

[Eric Wong]

Jeremy Kemper <jeremy@bitsweat.net> wrote:
> On Tue, Aug 11, 2009 at 9:38 PM, Eric Wong<normalperson@yhbt.net> wrote:
> > Eric Wong <normalperson@yhbt.net> wrote:
> >> Christian Neukirchen <chneukirchen@gmail.com> wrote:
> >> > Does it log the right size for chunked outputs?  In logfiles, I want those...

> >> This also miscalculates request time if the body is being generated
> >> dynamically during #each.

> Hey Eric,
> 
> Nice patch, but these changes were intentional. CommonLogger's concern
> is logging the request, not calculating content length edge cases or
> acting as a benchmarker. I'd advocate removing the timing entirely;
> it's not part of the Common Log Format.

Hi Jeremy,

Good point about the timing not being part of CLF.  I suppose everybody
could create their own BikeshedLogger since everybody I know has their
own ideas on what's useful/not useful in a logger :)

-- 
Eric Wong

Re: Downsizing CommonLogger

[Christian Neukirchen]

Jeremy Kemper <jeremy@bitsweat.net> writes:

> CommonLogger's concern
> is logging the request, not calculating content length edge cases

The CLF includes the real response size, though.  It should be correct
if you want to do traffic analysis with the existing tools.

-- 
Christian Neukirchen  <chneukirchen@gmail.com>  http://chneukirchen.org

Re: Downsizing CommonLogger

[Jeremy Kemper]

On Thu, Aug 13, 2009 at 5:14 AM, Christian
Neukirchen<chneukirchen@gmail.com> wrote:
>
> Jeremy Kemper <jeremy@bitsweat.net> writes:
>
>> CommonLogger's concern
>> is logging the request, not calculating content length edge cases
>
> The CLF includes the real response size, though.  It should be correct
> if you want to do traffic analysis with the existing tools.

There is no standard "real" size. Most log the size of the entity body
as represented by Content-Length. Some include HTTP header size. Few
actually record the number of bytes sent to the client (mog_logio for
apache does).

jeremy

Re: Downsizing CommonLogger

[Jeremy Kemper]

On Thu, Aug 13, 2009 at 11:18 AM, Jeremy Kemper<jeremy@bitsweat.net> wrote:
> On Thu, Aug 13, 2009 at 5:14 AM, Christian
> Neukirchen<chneukirchen@gmail.com> wrote:
>>
>> Jeremy Kemper <jeremy@bitsweat.net> writes:
>>
>>> CommonLogger's concern
>>> is logging the request, not calculating content length edge cases
>>
>> The CLF includes the real response size, though.  It should be correct
>> if you want to do traffic analysis with the existing tools.
>
> There is no standard "real" size. Most log the size of the entity body
> as represented by Content-Length. Some include HTTP header size. Few
> actually record the number of bytes sent to the client (mog_logio for
> apache does).

(nginx's http logger does, too.)

jeremy

Re: Downsizing CommonLogger

[Yehuda Katz]

[-- Attachment #1: Type: text/plain, Size: 1150 bytes --]

I'm personally quite concerned about trying to figure out the content-length
in any Rack middleware. It's expensive to do in pure-ruby, and a later
middleware can mess with the size anyway and be forced to recalculate. I
think the appropriate place for this calculation is in the actual server
that sends the data to the client, where it can be done once and in C.
-- Yehuda

On Thu, Aug 13, 2009 at 9:18 AM, Jeremy Kemper <jeremy@bitsweat.net> wrote:

>
> On Thu, Aug 13, 2009 at 5:14 AM, Christian
> Neukirchen<chneukirchen@gmail.com> wrote:
> >
> > Jeremy Kemper <jeremy@bitsweat.net> writes:
> >
> >> CommonLogger's concern
> >> is logging the request, not calculating content length edge cases
> >
> > The CLF includes the real response size, though.  It should be correct
> > if you want to do traffic analysis with the existing tools.
>
> There is no standard "real" size. Most log the size of the entity body
> as represented by Content-Length. Some include HTTP header size. Few
> actually record the number of bytes sent to the client (mog_logio for
> apache does).
>
> jeremy
>



-- 
Yehuda Katz
Developer | Engine Yard
(ph) 718.877.1325

[-- Attachment #2: Type: text/html, Size: 1700 bytes --]

Re: Downsizing CommonLogger

[Brian Lopez]

[-- Attachment #1: Type: text/plain, Size: 1262 bytes --]

Agreed.

-Brian

On Aug 13, 2009, at 9:30 AM, Yehuda Katz wrote:

> I'm personally quite concerned about trying to figure out the  
> content-length in any Rack middleware. It's expensive to do in pure- 
> ruby, and a later middleware can mess with the size anyway and be  
> forced to recalculate. I think the appropriate place for this  
> calculation is in the actual server that sends the data to the  
> client, where it can be done once and in C.
>
> -- Yehuda
>
> On Thu, Aug 13, 2009 at 9:18 AM, Jeremy Kemper <jeremy@bitsweat.net>  
> wrote:
>
> On Thu, Aug 13, 2009 at 5:14 AM, Christian
> Neukirchen<chneukirchen@gmail.com> wrote:
> >
> > Jeremy Kemper <jeremy@bitsweat.net> writes:
> >
> >> CommonLogger's concern
> >> is logging the request, not calculating content length edge cases
> >
> > The CLF includes the real response size, though.  It should be  
> correct
> > if you want to do traffic analysis with the existing tools.
>
> There is no standard "real" size. Most log the size of the entity body
> as represented by Content-Length. Some include HTTP header size. Few
> actually record the number of bytes sent to the client (mog_logio for
> apache does).
>
> jeremy
>
>
>
> -- 
> Yehuda Katz
> Developer | Engine Yard
> (ph) 718.877.1325


[-- Attachment #2: Type: text/html, Size: 1981 bytes --]

Re: Downsizing CommonLogger

[Jeremy Kemper]

On Thu, Aug 13, 2009 at 11:33 AM, Brian Lopez<seniorlopez@gmail.com> wrote:
> Agreed.
> -Brian
> On Aug 13, 2009, at 9:30 AM, Yehuda Katz wrote:
>
> I'm personally quite concerned about trying to figure out the content-length
> in any Rack middleware. It's expensive to do in pure-ruby, and a later
> middleware can mess with the size anyway and be forced to recalculate. I
> think the appropriate place for this calculation is in the actual server
> that sends the data to the client, where it can be done once and in C.
> -- Yehuda

On that note, this middleware could be downsized right out of rack
core and into -contrib's warm embrace.

jeremy

Re: Downsizing CommonLogger

[Scytrin dai Kinthra]

[-- Attachment #1: Type: text/plain, Size: 213 bytes --]

agreed.

--
stadik.net

On Aug 13, 2009 9:33 AM, "Brian Lopez" <seniorlopez@gmail.com> wrote:

Agreed.

-Brian

On Aug 13, 2009, at 9:30 AM, Yehuda Katz wrote: > I'm personally quite
concerned about trying to ...

[-- Attachment #2: Type: text/html, Size: 519 bytes --]

Re: Downsizing CommonLogger

[Eric Wong]

Yehuda Katz <wycats@gmail.com> wrote:
> I'm personally quite concerned about trying to figure out the content-length
> in any Rack middleware. It's expensive to do in pure-ruby, and a later
> middleware can mess with the size anyway and be forced to recalculate. I
> think the appropriate place for this calculation is in the actual server
> that sends the data to the client, where it can be done once and in C.
> -- Yehuda

If called in the correct place, the stock ContentLength middleware looks
fine to me, and still easier/faster for clients (especially caches) to
handle.  That said, I consider correct ordering of the middleware stack
to be a requirement anyways.

Of course, chunked transfers (if they're generated on the fly) are
impossible to calculate until the response is finished writing...  I'd
also rather not have my logs bound by whatever server-of-the-day I
happen to be using.

-- 
Eric Wong