Broken 404 handling #931

Closed
lgustafson opened this Issue Sep 12, 2012 · 20 comments

Comments

Projects
None yet
9 participants
@lgustafson

Padrino does not return a proper HTTP response for 404 Not Found errors, when running in :development environment using WEBrick (via "padrino s" or rackup). The "Content-Length" header is not set to a valid value and can cause unexpected behavior in an HTTP client.

This appears to be related to a change made in Sinatra 1.3.3 where in Sinatra::Response#finish the "Content-Length" header is not modified if it has already been set (see sinatra/sinatra@00b63ec). If I revert line 80 in the above commit it works correctly. Apparently, the "Content-Length" is being set by something upstream (Padrino?). I cannot reproduce the issue with core Sinatra.

Steps to reproduce:

  1. padrino g project test-app . && cd test-app
  2. padrino s
  3. curl -vv http://localhost:3000/invalid

The output will look something like this (note that the Content-Length is 30 but it should be 468.... re-run curl with --ignore-content-length and you'll see the full output):

* About to connect() to localhost port 3000 (#0)
*   Trying ::1...
* Connection refused
*   Trying 127.0.0.1...
* connected
* Connected to localhost (127.0.0.1) port 3000 (#0)
> GET /invalid HTTP/1.1
> User-Agent: curl/7.24.0 (x86_64-pc-linux-gnu) libcurl/7.24.0 OpenSSL/1.0.0h zlib/1.2.6 libidn/1.23 libssh2/1.2.8 librtmp/2.3
> Host: localhost:3000
> Accept: */*
> 
* additional stuff not fine transfer.c:1037: 0 0
* HTTP 1.1 or later with persistent connection, pipelining supported
< HTTP/1.1 404 Not Found 
< Content-Type: text/html;charset=utf-8
< Content-Length: 30
< X-Cascade: pass
< Server: WEBrick/1.3.1 (Ruby/1.9.3/2012-04-20)
< Date: Wed, 12 Sep 2012 02:46:47 GMT
< Connection: Keep-Alive
< 
* Excess found in a non pipelined read: excess = 413, size = 30, maxdownload = 30, bytecount = 0
<!DOCTYPE html>
<html>
<head>
* Connection #0 to host localhost left intact
* Closing connection #0
@drojo

This comment has been minimized.

Show comment
Hide comment
@drojo

drojo Sep 23, 2012

Great report. I have same issue, and this is my curl output:

  • About to connect() to localhost port 3000 (#0)
  • Trying 127.0.0.1... connected
  • Connected to localhost (127.0.0.1) port 3000 (#0)

    GET /invalid HTTP/1.1
    User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8r zlib/1.2.3
    Host: localhost:3000
    Accept: /

    < HTTP/1.1 404 Not Found
    < Connection: Keep-Alive
    < Content-Type: text/html;charset=utf-8
    < Date: Sun, 23 Sep 2012 13:20:29 GMT
    < X-Cascade: pass
    < Content-Length: 30
    < Server: WEBrick/1.3.1 (Ruby/1.8.7/2012-02-08)
    <
  • Rewinding stream by : 2600 bytes on url /invalid (size = 30, maxdownload = 30, bytecount = 0, nread = 2630)
    <!doctype html>
  • Connection #0 to host localhost left intact
  • Closing connection #0

drojo commented Sep 23, 2012

Great report. I have same issue, and this is my curl output:

  • About to connect() to localhost port 3000 (#0)
  • Trying 127.0.0.1... connected
  • Connected to localhost (127.0.0.1) port 3000 (#0)

    GET /invalid HTTP/1.1
    User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8r zlib/1.2.3
    Host: localhost:3000
    Accept: /

    < HTTP/1.1 404 Not Found
    < Connection: Keep-Alive
    < Content-Type: text/html;charset=utf-8
    < Date: Sun, 23 Sep 2012 13:20:29 GMT
    < X-Cascade: pass
    < Content-Length: 30
    < Server: WEBrick/1.3.1 (Ruby/1.8.7/2012-02-08)
    <
  • Rewinding stream by : 2600 bytes on url /invalid (size = 30, maxdownload = 30, bytecount = 0, nread = 2630)
    <!doctype html>
  • Connection #0 to host localhost left intact
  • Closing connection #0
@nesquena

This comment has been minimized.

Show comment
Hide comment
@nesquena

nesquena Sep 23, 2012

Member

Thanks for the reports, we hope to fix this in the next Padrino release

Member

nesquena commented Sep 23, 2012

Thanks for the reports, we hope to fix this in the next Padrino release

@DAddYE

This comment has been minimized.

Show comment
Hide comment
@DAddYE

DAddYE Sep 23, 2012

Member

Main problem here is that something in the latest sinatra broken something:

@nesquena: have you looked at this?

note that the Content-Length is 30 but it should be 468

Member

DAddYE commented Sep 23, 2012

Main problem here is that something in the latest sinatra broken something:

@nesquena: have you looked at this?

note that the Content-Length is 30 but it should be 468

@nesquena

This comment has been minimized.

Show comment
Hide comment
@nesquena

nesquena Sep 23, 2012

Member

Not yet, I will take a look soon.

Member

nesquena commented Sep 23, 2012

Not yet, I will take a look soon.

@lgustafson

This comment has been minimized.

Show comment
Hide comment
@lgustafson

lgustafson Sep 24, 2012

I'm fairly certain the changeset in Sinatra I linked to is the cause of this issue but that's as far as I've looked.

I'm fairly certain the changeset in Sinatra I linked to is the cause of this issue but that's as far as I've looked.

@DAddYE

This comment has been minimized.

Show comment
Hide comment
@DAddYE

DAddYE Sep 24, 2012

Member

thanks @lgustafson I didn't saw the link, btw I've added a comment sinatra/sinatra@00b63ec

ATM we can lock sinatra to old one.

Member

DAddYE commented Sep 24, 2012

thanks @lgustafson I didn't saw the link, btw I've added a comment sinatra/sinatra@00b63ec

ATM we can lock sinatra to old one.

@jormon

This comment has been minimized.

Show comment
Hide comment
@jormon

jormon Sep 25, 2012

I think @lgustafson is on the right track when he says 'Apparently, the "Content-Length" is being set by something upstream (Padrino?).' @lgustafson, can you report back what exactly Content-Length was set to by modifying the code just before the line in the sintra commit referenced by @DAddYE? Then it's just a matter of figuring out where it's being set invalidly.

jormon commented Sep 25, 2012

I think @lgustafson is on the right track when he says 'Apparently, the "Content-Length" is being set by something upstream (Padrino?).' @lgustafson, can you report back what exactly Content-Length was set to by modifying the code just before the line in the sintra commit referenced by @DAddYE? Then it's just a matter of figuring out where it's being set invalidly.

@wapcaplet

This comment has been minimized.

Show comment
Hide comment
@wapcaplet

wapcaplet Sep 28, 2012

+1, I just bumped into this with padrino 0.10.7 and sinatra 1.3.3. When requesting a bogus URL, I got:

127.0.0.1 - - [28/Sep/2012 11:50:50] "GET /favicon.ico HTTP/1.1" 404 30 0.0771
[2012-09-28 11:50:50] ERROR Rack::Lint::LintError: Content-Length header was 30, but should be 447
    /home/eric/.rvm/gems/ree-1.8.7-2012.02@sherman-manage/gems/rack-1.4.1/lib/rack/lint.rb:19:in `assert'

Reverting the sinatra commit mentioned by @lgustafson appears to fix it. I tried @jormon's suggestion, modifying lib/sinatra/base.rb to:

puts "Content-Length was #{headers['Content-Length']}" if headers['Content-Length']
headers["Content-Length"] = body.inject(0) { |l, p| l + Rack::Utils.bytesize(p) }.to_s
puts "Content-Length is now #{headers['Content-Length']}"

And got this output:

DEBUG -      GET (0.0788ms) /favicon.ico - 404 Not Found
127.0.0.1 - - [28/Sep/2012 12:09:22] "GET /favicon.ico HTTP/1.1" 404 447 0.0815
DEBUG -      GET (0.0537ms) /__sinatra__/404.png - 304 Not Modified
127.0.0.1 - - [28/Sep/2012 12:09:22] "GET /__sinatra__/404.png HTTP/1.1" 304 - 0.0556
Content-Length was 30
Content-Length is now 447

Maybe it's related to the content length of __sinatra__/404.png, rather than the content length of the bogus URL I'm requesting? Anyhow, I hope this helps. Meanwhile, I'm working around it by using Sinatra 1.3.2.

+1, I just bumped into this with padrino 0.10.7 and sinatra 1.3.3. When requesting a bogus URL, I got:

127.0.0.1 - - [28/Sep/2012 11:50:50] "GET /favicon.ico HTTP/1.1" 404 30 0.0771
[2012-09-28 11:50:50] ERROR Rack::Lint::LintError: Content-Length header was 30, but should be 447
    /home/eric/.rvm/gems/ree-1.8.7-2012.02@sherman-manage/gems/rack-1.4.1/lib/rack/lint.rb:19:in `assert'

Reverting the sinatra commit mentioned by @lgustafson appears to fix it. I tried @jormon's suggestion, modifying lib/sinatra/base.rb to:

puts "Content-Length was #{headers['Content-Length']}" if headers['Content-Length']
headers["Content-Length"] = body.inject(0) { |l, p| l + Rack::Utils.bytesize(p) }.to_s
puts "Content-Length is now #{headers['Content-Length']}"

And got this output:

DEBUG -      GET (0.0788ms) /favicon.ico - 404 Not Found
127.0.0.1 - - [28/Sep/2012 12:09:22] "GET /favicon.ico HTTP/1.1" 404 447 0.0815
DEBUG -      GET (0.0537ms) /__sinatra__/404.png - 304 Not Modified
127.0.0.1 - - [28/Sep/2012 12:09:22] "GET /__sinatra__/404.png HTTP/1.1" 304 - 0.0556
Content-Length was 30
Content-Length is now 447

Maybe it's related to the content length of __sinatra__/404.png, rather than the content length of the bogus URL I'm requesting? Anyhow, I hope this helps. Meanwhile, I'm working around it by using Sinatra 1.3.2.

@DAddYE DAddYE closed this Jan 5, 2013

@rkh

This comment has been minimized.

Show comment
Hide comment
@rkh

rkh Jan 5, 2013

Not really sure what's going on here, however, if this is a bug in Sinatra rather than Padrino, please report back upstream. :)

rkh commented Jan 5, 2013

Not really sure what's going on here, however, if this is a bug in Sinatra rather than Padrino, please report back upstream. :)

@DAddYE

This comment has been minimized.

Show comment
Hide comment
@DAddYE

DAddYE Jan 6, 2013

Member

@rkh I reported that in august, I don't remember the issue number but if I remember correctly was introduced by a pull request about file handling or so... :(

Member

DAddYE commented Jan 6, 2013

@rkh I reported that in august, I don't remember the issue number but if I remember correctly was introduced by a pull request about file handling or so... :(

@rkh

This comment has been minimized.

Show comment
Hide comment
@rkh

rkh Jan 6, 2013

OK, my bet then, just wanted to make sure this doesn't get lost on my end. Will get around to doing Sinatra housekeeping and new releases soon.

rkh commented Jan 6, 2013

OK, my bet then, just wanted to make sure this doesn't get lost on my end. Will get around to doing Sinatra housekeeping and new releases soon.

@DAddYE

This comment has been minimized.

Show comment
Hide comment
@DAddYE

DAddYE Jan 6, 2013

Member

Thanks man!

Appreciated

On 06/gen/2013, at 02:38, Konstantin Haase notifications@github.com wrote:

OK, my bet then, just wanted to make sure this doesn't get lost. Will get around to doing Sinatra housekeeping and new releases soon.


Reply to this email directly or view it on GitHub.

Member

DAddYE commented Jan 6, 2013

Thanks man!

Appreciated

On 06/gen/2013, at 02:38, Konstantin Haase notifications@github.com wrote:

OK, my bet then, just wanted to make sure this doesn't get lost. Will get around to doing Sinatra housekeeping and new releases soon.


Reply to this email directly or view it on GitHub.

@stefl

This comment has been minimized.

Show comment
Hide comment
@stefl

stefl Jan 9, 2013

I'm having the same problem. Rolling back from 1.3.3 to 1.3.2 resolved it for me.

stefl commented Jan 9, 2013

I'm having the same problem. Rolling back from 1.3.3 to 1.3.2 resolved it for me.

@nesquena

This comment has been minimized.

Show comment
Hide comment
@nesquena

nesquena Jan 9, 2013

Member

Yeah unfortunately until we track this down we are tied to 1.3.2 :(

Member

nesquena commented Jan 9, 2013

Yeah unfortunately until we track this down we are tied to 1.3.2 :(

@dariocravero

This comment has been minimized.

Show comment
Hide comment
@dariocravero

dariocravero Jan 9, 2013

Contributor

So we should hold off of #983 and instead tie the version to 1.3.2 for now?

Contributor

dariocravero commented Jan 9, 2013

So we should hold off of #983 and instead tie the version to 1.3.2 for now?

@nesquena

This comment has been minimized.

Show comment
Hide comment
@nesquena

nesquena Jan 10, 2013

Member

This may have been fixed in Padrino edge here #949? @stefl Can you try with edge and sinatra 1.3.3 and see if this problem persists?

Member

nesquena commented Jan 10, 2013

This may have been fixed in Padrino edge here #949? @stefl Can you try with edge and sinatra 1.3.3 and see if this problem persists?

@stefl

This comment has been minimized.

Show comment
Hide comment
@stefl

stefl Jan 10, 2013

By edge I'm presuming"

gem 'padrino', :git => "https://github.com/padrino/padrino-framework.git"

I'm trying but I'm currently blocked by various gem dependency mismatches because of the activesupport bump.

I'll update shortly

stefl commented Jan 10, 2013

By edge I'm presuming"

gem 'padrino', :git => "https://github.com/padrino/padrino-framework.git"

I'm trying but I'm currently blocked by various gem dependency mismatches because of the activesupport bump.

I'll update shortly

@stefl

This comment has been minimized.

Show comment
Hide comment
@stefl

stefl Jan 10, 2013

Confirmed that this has now resolved the problem for me.

stefl commented Jan 10, 2013

Confirmed that this has now resolved the problem for me.

@nesquena

This comment has been minimized.

Show comment
Hide comment
@nesquena

nesquena Jan 29, 2013

Member

This may have been fixed in Sinatra 1.3.4 sinatra/sinatra@bc183f6 such that this hack could be reverted. We should investigate if that's the case and lock Padrino to Sinatra 1.3.4

Member

nesquena commented Jan 29, 2013

This may have been fixed in Sinatra 1.3.4 sinatra/sinatra@bc183f6 such that this hack could be reverted. We should investigate if that's the case and lock Padrino to Sinatra 1.3.4

@DAddYE

This comment has been minimized.

Show comment
Hide comment
@DAddYE

DAddYE Jan 30, 2013

Member

:1: do it and lock it ;)

Sent from my iPhone

On 28/gen/2013, at 23:47, Nathan Esquenazi notifications@github.com wrote:

This may have been fixed in Sinatra 1.3.4
sinatra/sinatra@bc183f6sinatra/sinatra@bc183f6
that this hack could be reverted. We should investigate if that's the
case and lock Padrino to 1.3.4


Reply to this email directly or view it on
GitHubhttps://github.com/padrino/padrino-framework/issues/931#issuecomment-12823849.

Member

DAddYE commented Jan 30, 2013

:1: do it and lock it ;)

Sent from my iPhone

On 28/gen/2013, at 23:47, Nathan Esquenazi notifications@github.com wrote:

This may have been fixed in Sinatra 1.3.4
sinatra/sinatra@bc183f6sinatra/sinatra@bc183f6
that this hack could be reverted. We should investigate if that's the
case and lock Padrino to 1.3.4


Reply to this email directly or view it on
GitHubhttps://github.com/padrino/padrino-framework/issues/931#issuecomment-12823849.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment