From mboxrd@z Thu Jan 1 00:00:00 1970 Delivered-To: chneukirchen@gmail.com Received: by 10.204.72.79 with SMTP id l15cs687150bkj; Tue, 11 Aug 2009 19:38:23 -0700 (PDT) Received-SPF: pass (google.com: domain of grbounce-ceibQwUAAAB4YPBqaDIjI2bFOCxyyh3G=chneukirchen=gmail.com@googlegroups.com designates 10.142.134.20 as permitted sender) client-ip=10.142.134.20; Authentication-Results: mr.google.com; spf=pass (google.com: domain of grbounce-ceibQwUAAAB4YPBqaDIjI2bFOCxyyh3G=chneukirchen=gmail.com@googlegroups.com designates 10.142.134.20 as permitted sender) smtp.mail=grbounce-ceibQwUAAAB4YPBqaDIjI2bFOCxyyh3G=chneukirchen=gmail.com@googlegroups.com; dkim=pass header.i=grbounce-ceibQwUAAAB4YPBqaDIjI2bFOCxyyh3G=chneukirchen=gmail.com@googlegroups.com Received: from mr.google.com ([10.142.134.20]) by 10.142.134.20 with SMTP id h20mr747544wfd.15.1250044701936 (num_hops = 1); Tue, 11 Aug 2009 19:38:21 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=googlegroups.com; s=beta; h=domainkey-signature:received:received:x-sender:x-apparently-to :received:received:received-spf:authentication-results:received:date :from:to:subject:message-id:references:mime-version:content-type :content-disposition:in-reply-to:user-agent:reply-to:sender :precedence:x-google-loop:mailing-list:list-id:list-post:list-help :list-unsubscribe:x-beenthere-env:x-beenthere; bh=QEX/R7AgjrohKfydGGs0zhuJ9KpUzPsT/2cbd6U8QD0=; b=l18W1tc3qDmVCAt02JWt1JWbtUgp7UDQYV53xqgH6BJJznnd3D9Ok4afZ3v1vatrcG DwnXHq7zQ2rjUy1oygB7sOGT5WWN/OZmVbJR+e3U227IYvr4cIR69Voh8beaA/nxi1S/ 62DQeFwUJYRJK0z1vUTsWDO9vRQernP8Wk8Ms= DomainKey-Signature: a=rsa-sha1; c=nofws; d=googlegroups.com; s=beta; h=x-sender:x-apparently-to:received-spf:authentication-results:date :from:to:subject:message-id:references:mime-version:content-type :content-disposition:in-reply-to:user-agent:reply-to:sender :precedence:x-google-loop:mailing-list:list-id:list-post:list-help :list-unsubscribe:x-beenthere-env:x-beenthere; b=KvdJVbtsd0TOODw+Azznfoku61PvS500EhajQFO54ySG25AYe/MxEjTN5kOW0c1COi oG02a1ZeOOzVDSkjEqXdHnV0vmDJ9tf4hA8fePi+Ek0twVpYq7WI6AvoR4HJ26eLqSOK ZkN3PgDEUkcErraIf1X8RmV/lQsGL/8oQjXFk= Received: by 10.142.134.20 with SMTP id h20mr134731wfd.15.1250044701598; Tue, 11 Aug 2009 19:38:21 -0700 (PDT) Received: by 10.107.171.33 with SMTP id y33gr1568pro.0; Tue, 11 Aug 2009 19:38:15 -0700 (PDT) X-Sender: normalperson@yhbt.net X-Apparently-To: rack-devel@googlegroups.com Received: by 10.141.3.12 with SMTP id f12mr4873220rvi.27.1250044694481; Tue, 11 Aug 2009 19:38:14 -0700 (PDT) Return-Path: Received: from dcvr.yhbt.net (dcvr.yhbt.net [64.71.152.64]) by gmr-mx.google.com with ESMTP id 24si606830pzk.13.2009.08.11.19.38.14; Tue, 11 Aug 2009 19:38:14 -0700 (PDT) Received-SPF: pass (google.com: best guess record for domain of normalperson@yhbt.net designates 64.71.152.64 as permitted sender) client-ip=64.71.152.64; Authentication-Results: gmr-mx.google.com; spf=pass (google.com: best guess record for domain of normalperson@yhbt.net designates 64.71.152.64 as permitted sender) smtp.mail=normalperson@yhbt.net Received: from localhost (unknown [12.186.229.34]) (using TLSv1 with cipher DHE-RSA-AES128-SHA (128/128 bits)) (No client certificate requested) by dcvr.yhbt.net (Postfix) with ESMTPSA id 9799A1F798; Wed, 12 Aug 2009 02:38:13 +0000 (UTC) Date: Tue, 11 Aug 2009 19:38:13 -0700 From: Eric Wong To: rack-devel@googlegroups.com Subject: Re: Downsizing CommonLogger Message-ID: <20090812023813.GA5916@dcvr.yhbt.net> References: <69a2885c0904290803j292d2c45j5a46d0e759b6272a@mail.gmail.com> <20090430002127.7bd983f1@sigma.localdomain> <69a2885c0905131852h2ee62731o72337bec5490742e@mail.gmail.com> <2a8d4a710905132214s1cb24b4brea19d6f684be20c7@mail.gmail.com> <1c5622660905140728i3c162e1erf2e3058f79c80357@mail.gmail.com> <20090812011427.GA4737@dcvr.yhbt.net> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20090812011427.GA4737@dcvr.yhbt.net> User-Agent: Mutt/1.5.18 (2008-05-17) Reply-To: rack-devel@googlegroups.com Sender: rack-devel@googlegroups.com Precedence: bulk X-Google-Loop: groups Mailing-List: list rack-devel@googlegroups.com; contact rack-devel+owner@googlegroups.com List-Id: List-Post: List-Help: List-Unsubscribe: , X-BeenThere-Env: rack-devel@googlegroups.com X-BeenThere: rack-devel@googlegroups.com Eric Wong wrote: > Christian Neukirchen wrote: > > Joshua Peek 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