Odd http header corruption

Hi there,

I can’t tell if this is a problem with the ruby cgi library or with
rails action pack (no response from the rails list so far), but I get an
occasional error in the http headers from rails like this:

HTTP/1.x 200 OK
Date: Thu, 02 Feb 2006 20:56:03 GMT
Server: Apache/2.0.54 (Debian GNU/Linux) PHP/4.3.10-16 mod_ruby/1.2.4
Ruby/1.8.4(2005-12-24)
#<#<Class: 0x40b8e99c>:0x40b8e8d4>Content-Type: text/html
Cache-Control: no-cache

Some kind of object data is getting dumped in front of the Content-Type,
which screws up how some browsers display the page.

Setting Content-Type explicitly in the controller doesn’t seem to help,
and so far I have been unable to detect what causes this, or why it
happens under some circumstances and not others - I am posting this here
in case anybody has seen something similar, or has ideas about possible
causes.

Many thanks

CHEERS> SAM

Hi,

So more information on the header corruption.

I tried adding a slice! instruction to remove the offending part of the
http headers. Rails ActionController::CgiResponse normally uses the
following:

output.write(@cgi.header(@headers))

which I replaced with:

headers = @cgi.header(@headers)
headers.slice!(/#<#<(C|c)lass: 0x[\w\d]>:0x[\w\d]>/)
output.write(headers)

testing that my regex really did match the offending string.

However, this addition did not remove the offending string, and writing
the headers out into the body of the response gave me this

Content-Type: text/html
Set-Cookie: _session_id=936ba003910da551a472708d4b7b3ff3; path=/
Status: 200 OK
Cache-Control: no-cache

suggesting to me that the problem was being introduced at a different
stage … However, superficially I cannot work out how this set of
headers is actually transformed into the headers we see in the HTTP
header itself which looks like this:

HTTP/1.x 200 OK
Date: Tue, 07 Feb 2006 13:59:08 GMT
Server: Apache/2.0.54 (Debian GNU/Linux) PHP/4.3.10-16
#<#<Class: 0x40bdaff4>:0x40bdaf2c>Content-Type: text/html
Cache-Control: no-cache
Set-Cookie: _session_id=936ba003910da551a472708d4b7b3ff3; path=/
Keep-Alive: timeout=15, max=100
Connection: Keep-Alive
Transfer-Encoding: chunked
Content-Type: text/plain

The implication being that the header string is transformed somewhere
that I have been unable to determine.

I’ve even checked by dumping the @cgi, @headers and ENV objects as YAML
into the HTML body, and then reassembling them locally. As far as I can
tell, within rails, the operation:

@cgi.header(@headers)

generates a string like:

Content-Type: text/html
Set-Cookie: _session_id=936ba003910da551a472708d4b7b3ff3; path=/
Status: 200 OK
Cache-Control: no-cache

but the output from rails through Apache is a properly formed HTTP
header.

From looking at the ruby cgi library, I can see that if I was using
mod_ruby that the output would be different, and would be directed
straight to Apache, but I’m not using mod_ruby, so now I have two
problems:

  1. I can’t work out how the results of calling @cgi.header(@headers) in
    rails actually gets turned into a real HTTP response
  2. I still can’t see where this strange string is being introduced

I have discovered a work around that is a bit of a hack, but I will post
the patch to the rails ticket I have opened:

http://dev.rubyonrails.org/ticket/3703

I’d still like to work out what causes this problem so I can properly be
rid of it.

Another very weird thing is that I appear to be able to comment out the
contents of the process_cgi method in actioncontrollers cgi_process.rb,
but that things still keep functioning - other changes in the same file
have effects on the http output, just not for the process_cgi method,
which is the only place I can see in the code where the CgiResponse out
method gets called. Clearly I’m still missing a big chunk of this
puzzle.

CHEERS> SAM

On Feb 6, 2006, at 1:16 AM, Sam J. wrote:

Ruby/1.8.4(2005-12-24)
#<#<Class: 0x40b8e99c>:0x40b8e8d4>Content-Type: text/html
Cache-Control: no-cache

You’re adding a metaclass thingy to your headers.

possible
causes.

Does it go away if you take that out?

I’m going to blame your code or Rails on this one.


Eric H. - [email protected] - http://segment7.net
This implementation is HODEL-HASH-9600 compliant

http://trackmap.robotcoop.com

Hello Sam,

On Wed, 08 Feb 2006 02:45:27 +0900, Sam J. [email protected]
wrote:

header itself which looks like this:
Content-Type: text/plain
This looks like you have a “puts someobj.inspect” in your code.
Depending upon how you are running your system this rogue puts is
being called before the header output and is going directly to the
output stream. This is why your attempt to cut it out does not work.

I would grep your code for an “inspect” and if that fails “puts”.
Hopefully, that show you where the problem is.

Cheers,
Zev

Hi Zev,

Zev B. wrote:

This looks like you have a “puts someobj.inspect” in your code.
Depending upon how you are running your system this rogue puts is
being called before the header output and is going directly to the
output stream. This is why your attempt to cut it out does not work.

Indeed I have suspected as much.

I would grep your code for an “inspect” and if that fails “puts”.

I had already done so - I have no “puts” or “print” outside my test
classes, and no inspects outside of my logging code. I’ve used the
eclipse search function to scan all the code, and find | xargs grep on
the server. The only things that I can imagine being remotely
responsible are things like:

./app/models/message.rb: raise “more than one read_message for this
user/message pair #{self.inspect}, #{user.inspect}”

and

./app/controllers/application.rb: logger.info 'error during
workspace log: ’ + e.inspect

but these wouldn’t affect stdout right?

I’m sure there must be something dumping that information somewhere, but
I can’t find it in my code, or in rails code, and more disturbingly to
me, I can’t work out where in the rails code the first part of the http
header is generated, i.e. ‘HTTP/1.x 200 OK’, since the first call to
output in cgi_process.rb is:

output.write(@cgi.header(@headers))

and @cgi.header(@headers) doesn’t produce the first three lines of the
http header as far as I can see, yet there are no other calls to output
anything before that.

Anyhow, I’ve worked around the problem by printing a new line before the
@cgi.header(@headers) is printed, which has fixed things for the time
being.

CHEERS> SAM

On Feb 8, 2006, at 9:16 AM, Sam J. wrote:

the first part of the http header is generated, i.e. 'HTTP/1.x 200
for the time being.

CHEERS> SAM

Heres a thought:

use breakpoint to let you jump in after you produce the headers. Go
to the offending page, copy the inspect string of the object and in
the breakpoint session do something along the lines of the following:

ObjectSpace.to_enum(:each_object).find { |x| x.inspect ==
pasted_inspect_string }.try_some_methods_to_figure_out_where_this_guy_is
_from

On Feb 8, 2006, at 6:18 AM, Sam J. wrote:

Date: Thu, 02 Feb 2006 20:56:03 GMT
Some kind of object data is getting dumped in front of the
causes.

HTTP/1.x 200 OK
Date: Thu, 02 Feb 2006 20:56:03 GMT
Server: Apache/2.0.54 (Debian GNU/Linux) PHP/4.3.10-16

Since placing a newline before any output from CgiReponse.out
places that new line after these three lines, so where are they
generated? I can’t work it out.

They are generated by Apache. What do you get when you run
dispatch.cgi from the command line?


Eric H. - [email protected] - http://segment7.net
This implementation is HODEL-HASH-9600 compliant

http://trackmap.robotcoop.com

Hi Eric,

Eric H. wrote:

Date: Thu, 02 Feb 2006 20:56:03 GMT
Server: Apache/2.0.54 (Debian GNU/Linux) PHP/4.3.10-16 mod_ruby/1.2.4
Ruby/1.8.4(2005-12-24)
#<#<Class: 0x40b8e99c>:0x40b8e8d4>Content-Type: text/html
Cache-Control: no-cache

You’re adding a metaclass thingy to your headers.

Indeed - not intentionally I assure you :slight_smile:

causes.

Does it go away if you take that out?

No

I’m going to blame your code or Rails on this one.

Or some interaction of the two :slight_smile: The thing I’m really keen to work
out is how the actioncontroller cgi_process.rb generates the output
before the odd thingy, i.e.

HTTP/1.x 200 OK
Date: Thu, 02 Feb 2006 20:56:03 GMT
Server: Apache/2.0.54 (Debian GNU/Linux) PHP/4.3.10-16

Since placing a newline before any output from CgiReponse.out places
that new line after these three lines, so where are they generated? I
can’t work it out.

Many thanks.

CHEERS> SAM

Eric H. wrote:

Since placing a newline before any output from CgiReponse.out places
that new line after these three lines, so where are they generated?
I can’t work it out.

They are generated by Apache.

Ah that makes sense.

What do you get when you run dispatch.cgi from the command line?

I get:

Status: 500 Internal Server Error

The only operational code I see in dispatch.cgi is Dispatcher.dispatch -
I guess that’s just passing the incoming request to the appropriate
controller. I guess you’re saying that Apache prints the first three
lines, and then appends the rest of the output from rails. But
presumably the status code needs to be communicated from rails to Apache

  • do you know how this happens? I guess Apache cgi handler is taking
    the:

Status: 200 OK
Content-Type: text/html
Cache-Control: no-cache

that process_cgi.rb outputs (via dispatch.cgi) and then forms the
complete HTTP header as a function of that.

That makes sense now. I guess it would be nice to be able to call
dispatch.cgi from the command line passing in the appropriate parameters
to see exactly what it spits back … I tried the following:

./dispatch.cgi /discussions/tree/1
Status: 500 Internal Server Error

so it’s not as simple as that.

CHEERS> SAM

On Feb 9, 2006, at 9:48 AM, Sam J. wrote:

Server: Apache/2.0.54 (Debian GNU/Linux) PHP/4.3.10-16

I get:

Status: 500 Internal Server Error

The only operational code I see in dispatch.cgi is
Dispatcher.dispatch - I guess that’s just passing the incoming
request to the appropriate controller. I guess you’re saying that
Apache prints the first three lines, and then appends the rest of
the output from rails. But presumably the status code needs to be
communicated from rails to Apache - do you know how this happens?

It is part of the CGI “spec”.

That makes sense now. I guess it would be nice to be able to call
dispatch.cgi from the command line passing in the appropriate
parameters to see exactly what it spits back … I tried the
following:

./dispatch.cgi /discussions/tree/1
Status: 500 Internal Server Error

so it’s not as simple as that.

You need to set up the complete request environment first. Things
like REQUEST_METHOD and PATH_INFO and so-forth.


Eric H. - [email protected] - http://segment7.net
This implementation is HODEL-HASH-9600 compliant

http://trackmap.robotcoop.com

Sam J. wrote:

That makes sense now. I guess it would be nice to be able to call
dispatch.cgi from the command line passing in the appropriate parameters
to see exactly what it spits back … I tried the following:

./dispatch.cgi /discussions/tree/1
Status: 500 Internal Server Error

so it’s not as simple as that.

I think you need to preload the PATH_INFO environment variable

$ PATH_INFO=/discussions/tree/1; export PATH_INFO
$ ./dispatch.cgi

(Or SCRIPT_NAME or something like that.)


James B.

http://www.ruby-doc.org - Ruby Help & Documentation
Ruby Code & Style - The Journal By & For Rubyists
http://www.rubystuff.com - The Ruby Store for Ruby Stuff
http://www.30secondrule.com - Building Better Tools