CommonLogger (and Clogger) generates strange symbols in the response body

CommonLogger (and Clogger) generates strange symbols in the response body

[Iñaki Baz Castillo]

Hi, I can't understand why the following issue occurs in the response body 
when using CommonLogger:


----- app_logic.rb -----
class AppLogic
  def call(env)
    200, {"Content-Type" => "text/plain"}, "line1\nline2\nline3\n"
  end
end
------------------------


------- run_server.rb ------
require "app_logic.rb"
rack_inner_app = AppLogic.new

rack_app = Rack::Builder.new {
  use Rack::CommonLogger, $stderr
  run rack_inner_app
}.to_app

Rack::Handler::Thin.run rack_app
----------------------------



The reply I get in the 200 OK response is as follows:

-------------
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: text/plain
Server: OpenXDMS
Connection: close

6
line1

6
line2

6
line3

0

-------------

As you can see, the number above each real body line is the length of the line 
below it (in hexadecimal when > 10).


If I comment the CommonLogger line, then I get the correct body:

--------------
line1
line2
line3
--------------



It occurs the same if I log to a file and also if I use Clogger instead of 
CommonLogger.

Is there something wrong in my code? is it the expected behaviour? (I cannot 
figure it of course as it breaks the response).


Thanks a lot.



-- 
Iñaki Baz Castillo <ibc@aliax.net>

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Iñaki Baz Castillo]

El Viernes, 4 de Septiembre de 2009, Iñaki Baz Castillo escribió:
> Hi, I can't understand why the following issue occurs in the response body
> when using CommonLogger:
> 
> 
> ----- app_logic.rb -----
> class AppLogic
>   def call(env)
>     200, {"Content-Type" => "text/plain"}, "line1\nline2\nline3\n"
>   end
> end
> ------------------------
> 
> 
> ------- run_server.rb ------
> require "app_logic.rb"
> rack_inner_app = AppLogic.new
> 
> rack_app = Rack::Builder.new {
>   use Rack::CommonLogger, $stderr
>   run rack_inner_app
> }.to_app
> 
> Rack::Handler::Thin.run rack_app
> ----------------------------
> 
> 
> 
> The reply I get in the 200 OK response is as follows:
> 
> -------------
> HTTP/1.1 200 OK
> Transfer-Encoding: chunked
> Content-Type: text/plain
> Server: OpenXDMS
> Connection: close
> 
> 6
> line1
> 
> 6
> line2
> 
> 6
> line3
> 
> 0
> 
> -------------
> 
> As you can see, the number above each real body line is the length of the
>  line below it (in hexadecimal when > 10).
> 
> 
> If I comment the CommonLogger line, then I get the correct body:
> 
> --------------
> line1
> line2
> line3
> --------------
> 
> 
> 
> It occurs the same if I log to a file and also if I use Clogger instead of
> CommonLogger.
> 
> Is there something wrong in my code? is it the expected behaviour? (I
>  cannot figure it of course as it breaks the response).

It's not an error in my code as a simpler example also issues this problem:

-----simple_rack.rb--------
require 'rubygems'
require 'rack'

infinity = Proc.new {|env| [200, {"Content-Type" => "text/html"}, "hello"]}
builder = Rack::Builder.new do
  use Rack::CommonLogger
  run infinity
end
Rack::Handler::Mongrel.run builder, :Port => 9292
---------------------------

~# ruby1.8 simple_rack.rb


And this is the response:

---------------------------
HTTP/1.1 200 OK
Connection: close
Date: Thu, 03 Sep 2009 23:24:39 GMT
Transfer-Encoding: chunked
Content-Type: text/html

4
hello
0

---------------------------


Without the CommonLogger middleware, the response body is correct:

----------
hello
----------



¿?¿?

-- 
Iñaki Baz Castillo <ibc@aliax.net>

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Eric Wong]

Iñaki Baz Castillo <ibc@aliax.net> wrote:
> 
> Hi, I can't understand why the following issue occurs in the response body 
> when using CommonLogger:
> 
> 
> ----- app_logic.rb -----
> class AppLogic
>   def call(env)
>     200, {"Content-Type" => "text/plain"}, "line1\nline2\nline3\n"
>   end
> end
> ------------------------
> 
> 
> ------- run_server.rb ------
> require "app_logic.rb"
> rack_inner_app = AppLogic.new
> 
> rack_app = Rack::Builder.new {
>   use Rack::CommonLogger, $stderr
>   run rack_inner_app
> }.to_app
> 
> Rack::Handler::Thin.run rack_app
> ----------------------------
> 
> 
> 
> The reply I get in the 200 OK response is as follows:
> 
> -------------
> HTTP/1.1 200 OK
> Transfer-Encoding: chunked
> Content-Type: text/plain
> Server: OpenXDMS
> Connection: close
> 
> 6
> line1
> 
> 6
> line2
> 
> 6
> line3
> 
> 0
> 
> -------------
> 
> As you can see, the number above each real body line is the length of the line 
> below it (in hexadecimal when > 10).

This is chunked transfer encoding as defined in rfc 2616, section 3.6.1.
Any HTTP/1.1 client should be able to interpret and decode it correctly.

Both CommonLogger (from Rack 1.0) and Clogger (by default) wraps the
original response body with something that responds to #each to
correctly calculate the size of the body.  This can throw off the
Rack::ContentLength middleware that your server probably already loads
for you (the Thin and Mongrel handlers both appear to load both
Rack::Chunked and Rack::ContentLength).

For performance reasons, the next version of Rack will instead log the
existing "Content-Length" header if one exists, and '-' if it doesn't;
skipping the wrapping of the body[1].

> It occurs the same if I log to a file and also if I use Clogger instead of 
> CommonLogger.
> 
> Is there something wrong in my code? is it the expected behaviour? (I cannot 
> figure it of course as it breaks the response).

Yes, it's correct behavior, the response is not broken.

[1] - on a side note, one of the reasons I started Clogger was to
      preserve the existing body length calculation behavior.
-- 
Eric Wong

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Iñaki Baz Castillo]

2009/9/4 Eric Wong <normalperson@yhbt.net>:
>> As you can see, the number above each real body line is the length of the line
>> below it (in hexadecimal when > 10).
>
> This is chunked transfer encoding as defined in rfc 2616, section 3.6.1.
> Any HTTP/1.1 client should be able to interpret and decode it correctly.

Thanks a lot, I didn't know it.


> Both CommonLogger (from Rack 1.0) and Clogger (by default) wraps the
> original response body with something that responds to #each to
> correctly calculate the size of the body.  This can throw off the
> Rack::ContentLength middleware that your server probably already loads
> for you (the Thin and Mongrel handlers both appear to load both
> Rack::Chunked and Rack::ContentLength).
>
> For performance reasons, the next version of Rack will instead log the
> existing "Content-Length" header if one exists, and '-' if it doesn't;
> skipping the wrapping of the body[1].

Does it mean that with the next version I would get a non chunked
transfer encoded body even if I use CommonLogger?

Thanks a lot.


-- 
Iñaki Baz Castillo
<ibc@aliax.net>

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Eric Wong]

Iñaki Baz Castillo <ibc@aliax.net> wrote:
> > This is chunked transfer encoding as defined in rfc 2616, section 3.6.1.
> > Any HTTP/1.1 client should be able to interpret and decode it correctly.
> 
> Thanks a lot, I didn't know it.

No problem

> > Both CommonLogger (from Rack 1.0) and Clogger (by default) wraps the
> > original response body with something that responds to #each to
> > correctly calculate the size of the body.  This can throw off the
> > Rack::ContentLength middleware that your server probably already loads
> > for you (the Thin and Mongrel handlers both appear to load both
> > Rack::Chunked and Rack::ContentLength).
> >
> > For performance reasons, the next version of Rack will instead log the
> > existing "Content-Length" header if one exists, and '-' if it doesn't;
> > skipping the wrapping of the body[1].
> 
> Does it mean that with the next version I would get a non chunked
> transfer encoded body even if I use CommonLogger?
> 
> Thanks a lot.

Yes, however you might want to load the Rack::ContentLength middleware
in front of CommonLogger to ensure the length can get logged correctly
as a result.

-- 
Eric Wong

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Iñaki Baz Castillo]

El Viernes, 4 de Septiembre de 2009, Eric Wong escribió:

> > > For performance reasons, the next version of Rack will instead log the
> > > existing "Content-Length" header if one exists, and '-' if it doesn't;
> > > skipping the wrapping of the body[1].
> >
> > Does it mean that with the next version I would get a non chunked
> > transfer encoded body even if I use CommonLogger?
> >
> 
> Yes, however you might want to load the Rack::ContentLength middleware
> in front of CommonLogger to ensure the length can get logged correctly
> as a result.

But if I use Clogger then I don't need to add Rack::ContentLength, right?

Thanks again.


-- 
Iñaki Baz Castillo <ibc@aliax.net>

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Eric Wong]

Iñaki Baz Castillo <ibc@aliax.net> wrote:
> El Viernes, 4 de Septiembre de 2009, Eric Wong escribió:
> 
> > > > For performance reasons, the next version of Rack will instead log the
> > > > existing "Content-Length" header if one exists, and '-' if it doesn't;
> > > > skipping the wrapping of the body[1].
> > >
> > > Does it mean that with the next version I would get a non chunked
> > > transfer encoded body even if I use CommonLogger?
> > >
> > Yes, however you might want to load the Rack::ContentLength middleware
> > in front of CommonLogger to ensure the length can get logged correctly
> > as a result.
> 
> But if I use Clogger then I don't need to add Rack::ContentLength, right?

With $body_bytes_sent or $response_length, then no, you don't need to
load Rack::ContentLength in front of Clogger.  But you can avoid a
chunked body if you do load Rack::ContentLength.

> Thanks again.

No problem!

-- 
Eric Wong

Re: CommonLogger (and Clogger) generates strange symbols in the response body

[Iñaki Baz Castillo]

El Viernes, 4 de Septiembre de 2009, Eric Wong escribió:
> With $body_bytes_sent or $response_length, then no, you don't need to
> load Rack::ContentLength in front of Clogger.  But you can avoid a
> chunked body if you do load Rack::ContentLength.

Ahh, ok, that's nice to know.

Thanks. 


-- 
Iñaki Baz Castillo <ibc@aliax.net>