Rocket // HTTP 400 Bad Request - Body is incomplete

[Louis Amon]

I made some changes to my code and it seems I broke some stuff.

Problem is : instead of getting a ticket, my POST request is stalled and my console is displaying this error :

ERROR - 27-12-2014 17:16:27 - Rocket.Errors.Thread-10 : Traceback (most recent call last):

 File "/opt/web2py-prod/gluon/rocket.py", line 1337, in run

    self.run_app(conn)

 File "/opt/web2py-prod/gluon/rocket.py", line 1838, in run_app

    output = self.app(environ, self.start_response)

 File "/opt/web2py-prod/gluon/main.py", line 651, in app_with_logging

    ret[0] = wsgiapp(environ, responder2)

 File "/opt/web2py-prod/gluon/main.py", line 562, in wsgibase

    return wsgibase(new_environ, responder)

 File "/opt/web2py-prod/gluon/main.py", line 532, in wsgibase

    if request.body:

 File "/opt/web2py-prod/gluon/globals.py", line 269, in body

    raise HTTP(400, "Bad Request - HTTP body is incomplete")

HTTP: 400 BAD REQUEST

How do I got about debugging this ?

What is the correct methodology for solving HTTP 400 issues ?

[Niphlod]

whoa, that seems to be an issue with copystream_progress (in gluon/globals.py), that is quite easy to debug.
Usually due to some weird issue with really huge POSTs, or streaming ones that don't carry the content-length attribute, or something reeeeaaally reaaaaally weird.

[Louis Amon]

If it’s easy to debug then how do I proceed ? :)

I’ve copied here the request headers from Google Chrome :

1. Request URL:
   http://localhost:8000/location/index/espace-de-stockage/la-seyne-sur-mer/1
2. Request Headers
1. Provisional headers are shown
2. Accept:
   text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
3. Content-Type:
   multipart/form-data; boundary=----WebKitFormBoundaryVA2zLBxC8ghUQD3D
4. Origin:
   http://localhost:8000
5. Referer:
   http://localhost:8000/location/index/espace-de-stockage/la-seyne-sur-mer/1
6. User-Agent:
   Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36
3. Request Payload
1. ------WebKitFormBoundaryVA2zLBxC8ghUQD3D Content-Disposition: form-data; name="start_date" 30/12/2014 ------WebKitFormBoundaryVA2zLBxC8ghUQD3D Content-Disposition: form-data; name="weeks" 0 ------WebKitFormBoundaryVA2zLBxC8ghUQD3D Content-Disposition: form-data; name="months" 2 ------WebKitFormBoundaryVA2zLBxC8ghUQD3D Content-Disposition: form-data; name="years" 0 ------WebKitFormBoundaryVA2zLBxC8ghUQD3D Content-Disposition: form-data; name="_formkey" 45d798b8-a585-4610-be6f-b911f4fea831 ------WebKitFormBoundaryVA2zLBxC8ghUQD3D Content-Disposition: form-data; name="_formname" booking/create ------WebKitFormBoundaryVA2zLBxC8ghUQD3D--

Le 27 déc. 2014 à 17:43, Niphlod <nip...@gmail.com> a écrit :

whoa, that seems to be an issue with copystream_progress (in gluon/globals.py), that is quite easy to debug.
Usually due to some weird issue with really huge POSTs, or streaming ones that don't carry the content-length attribute, or something reeeeaaally reaaaaally weird.

--
Resources:
- http://web2py.com
- http://web2py.com/book (Documentation)
- http://github.com/web2py/web2py (Source code)
- https://code.google.com/p/web2py/issues/list (Report Issues)
---
You received this message because you are subscribed to a topic in the Google Groups "web2py-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/web2py/YgO4uJLnGzc/unsubscribe.
To unsubscribe from this group and all its topics, send an email to web2py+un...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Niphlod]

put a few logging statements on copystream_progress and see where it explodes...

[Louis Amon]

/location/index/espace-de-stockage/la-seyne-sur-mer/1

copystream called with size=672

/error/ticket/index/

copystream called with size=672

<class 'socket.timeout'> timed out

/error/ticket/index/

copystream called with size=672

<class 'socket.timeout'> timed out

/error/ticket/index/

copystream called with size=672

<class 'socket.timeout'> timed out

/error/ticket/index/

copystream called with size=672

<class 'socket.timeout'> timed out

From what I understand the POST request is sent 4 times.

The first time, an exception is found so a ticket request is sent to my "error" application that handles tickets (configured in routes_onerror).

So the next 3 requests are sent to my ticket handler but they end up raising an IOError due to this line in fileutils.py (L465):

data = src.read(size)

The IOError itself gives little information. It just prints "timed out".

What bothers me though is that this error causes a top-level python error that completely stalls the server: I had to close my shell to actually shut it down.

[Louis Amon]

This is the request received by my ticket handler (I removed some big chunks so that it's readable):

_vars None

function index

_body None

args []

wsgi <gluon.main.LazyWSGI object at 0x111e5cdd0>

controller ticket

utcnow 2014-12-29 18:09:42.485011

url /error/ticket/index/

step None

now 2014-12-29 19:09:42.484998

is_local True

is_shell None

uuid error/127.0.0.1.2014-12-29.19-09-42.95417662-6fed-4364-8f6a-f9e467f66bb6

extension html

cid None

_post_vars None

_get_vars None

ajax False

is_https False

is_sheduler None

application error

client 127.0.0.1

is_restful False

And this is request.env (raw data):

content_length 672

HTTP_REFERER http://localhost:8000/location/index/espace-de-stockage/la-seyne-sur-mer/1

SERVER_SOFTWARE Rocket 1.2.6

SCRIPT_NAME 

REQUEST_METHOD POST

HTTP_ORIGIN http://localhost:8000

SERVER_PROTOCOL HTTP/1.1

web2py_path /opt/web2py-prod

CONTENT_LENGTH 672

wsgi_url_scheme http

server_name Orbital Station

WEB2PY_STATUS_CODE 500

wsgi_errors <open file '<stderr>', mode 'w' at 0x10c5fd1e0>

web2py_version 2.9.11-stable+timestamp.2014.09.15.23.35.11

wsgi_multiprocess False

wsgi.version (1, 0)

HTTP_CACHE_CONTROL max-age=0

HTTP_CONTENT_TYPE multipart/form-data; boundary=----WebKitFormBoundarybsXFgXJZPAWZABTt

request_uri /error/ticket/index?code=500&ticket=jestocke/127.0.0.1.2014-12-29.19-09-42.ac14c293-9460-46df-934c-d6da0579c5ac&requested_uri=%2Fjestocke%2Ffr%2Flocation%2Findex%2Fespace-de-stockage%2Fla-seyne-sur-mer%2F1&request_url=/location/index/espace-de-stockage/la-seyne-sur-mer/1

HTTP_ACCEPT text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8

__ROUTES_ONERROR__ True

http_connection keep-alive

local_hosts ['Orbital Station', '::1', '::ffff:127.0.0.1', '127.0.0.1']

script_name 

wsgi.multiprocess False

http_accept_encoding gzip, deflate

__routes_onerror__ True

PATH_INFO /error/ticket/index/

http_origin http://localhost:8000

QUERY_STRING code=500&ticket=jestocke/127.0.0.1.2014-12-29.19-09-42.ac14c293-9460-46df-934c-d6da0579c5ac&requested_uri=%2Fjestocke%2Ffr%2Flocation%2Findex%2Fespace-de-stockage%2Fla-seyne-sur-mer%2F1&request_url=/location/index/espace-de-stockage/la-seyne-sur-mer/1

cmd_args []

http_accept text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8

HTTP_USER_AGENT Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36

HTTP_CONNECTION keep-alive

REMOTE_ADDR 127.0.0.1

http_accept_language fr,en-US;q=0.8,en;q=0.6,de;q=0.4,ja;q=0.2

wsgi.url_scheme http

is_source True

server_port 8000

gluon_parent /opt/web2py-prod

HTTP_DNT 1

http_content_length 672

wsgi.multithread True

query_string code=500&ticket=jestocke/127.0.0.1.2014-12-29.19-09-42.ac14c293-9460-46df-934c-d6da0579c5ac&requested_uri=%2Fjestocke%2Ffr%2Flocation%2Findex%2Fespace-de-stockage%2Fla-seyne-sur-mer%2F1&request_url=/location/index/espace-de-stockage/la-seyne-sur-mer/1

wsgi_run_once False

wsgi.file_wrapper wsgiref.util.FileWrapper

HTTP_ACCEPT_ENCODING gzip, deflate

http_cache_control max-age=0

REMOTE_PORT 60871

wsgi_file_wrapper wsgiref.util.FileWrapper

applications_parent /opt/web2py-prod

request_method POST

WEB2PY_ORIGINAL_URI /location/index/espace-de-stockage/la-seyne-sur-mer/1

SERVER_PORT 8000

http_content_type multipart/form-data; boundary=----WebKitFormBoundarybsXFgXJZPAWZABTt

web2py_original_uri /error/ticket/index/?code=500&ticket=jestocke/127.0.0.1.2014-12-29.19-09-42.ac14c293-9460-46df-934c-d6da0579c5ac&requested_uri=%2Fjestocke%2Ffr%2Flocation%2Findex%2Fespace-de-stockage%2Fla-seyne-sur-mer%2F1&request_url=/location/index/espace-de-stockage/la-seyne-sur-mer/1

wsgi_multithread True

web2py_status_code 500

HTTP_HOST localhost:8000

content_type multipart/form-data; boundary=----WebKitFormBoundarybsXFgXJZPAWZABTt

REQUEST_URI /jestocke/fr/location/index/espace-de-stockage/la-seyne-sur-mer/1

wsgi.run_once False

wsgi.errors <open file '<stderr>', mode 'w' at 0x10c5fd1e0>

HTTP_ACCEPT_LANGUAGE fr,en-US;q=0.8,en;q=0.6,de;q=0.4,ja;q=0.2

app_folders set(['/opt/web2py-prod/applications/admin/', '/opt/web2py-prod/applications/jestocke/', '/opt/web2py-prod/applications/error/'])

HTTP_CONTENT_LENGTH 672

debugging False

http_user_agent Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36

server_protocol HTTP/1.1

SERVER_NAME Orbital Station

remote_addr 127.0.0.1

is_jython False

wsgi_version (1, 0)

wsgi_input <socket._fileobject object at 0x111d71a50>

server_software Rocket 1.2.6

wsgi.input <socket._fileobject object at 0x111d71a50>

http_host localhost:8000

path_info /error/ticket/index/

http_referer http://localhost:8000/location/index/espace-de-stockage/la-seyne-sur-mer/1

is_pypy False

remote_port 60871

db_sessions set([])

http_dnt 1

CONTENT_TYPE multipart/form-data; boundary=----WebKitFormBoundarybsXFgXJZPAWZABTt

folder /opt/web2py-prod/applications/error/

Looking at request.env.query_string, I think it's odd that request._get_vars is empty (None).

Something goes very wrong here, but I'm not sure what.

Any idea ?

[Niphlod]

you're not very fair in debugging if you have something different that processes the error: please simplify it and let the application alone catch the error, then inspect what goes on with logging calls into copystream...

[Louis Amon]

I've tested the native error handler (working fine) versus my custom error handler (generating HTTP 400 error + web2py stuck) :

The main difference between the two is that the native error handler doesn't generate an additional request while routes_onerror seems to generate an additional request that points to my error handler.

This second request goes through copystream_progress just fine, then calls copystream (at line 125 in globals.py).

In copystream, it gets stuck at line 465 in fileutils.py :

data = src.read(size)

This call to 'read' eventually times out.

I've tried catching the error like this :

try:
    data = src.read(size)
except Exception as e:
    print type(e), e

All it ever prints (after 10 seconds) is :

<class 'socket.timeout'> timed out

How can I further investigate this matter ?

[Niphlod]

the point of routes_onerror is EXACTLY to "intercept" the error and somewhat process it to display a nicer page to the end-user. I'd guess at this point that your controller handling the error has some bugs in it: would you care to trim it to the bare minimum to see if the error is in handling the "original" error ?

[Derek]

You are running this on a Mac OSX server? Python has issues with this kind of thing a long time and there is no fix.

[Derek]

Just a question, Amon, do you need to use Rocket, or can you use anyserver.py and try something like greenlets?

On Saturday, January 3, 2015 4:56:54 PM UTC-7, Louis Amon wrote:

[Derek]

Yeah, this is strange, I wonder why Rocket reports it's version as 1.2.6 when the latest version of Rocket is 1.2.4?

[Massimo Di Pierro]

The version of rocket that ships with web2py is 1.2.6.

But what version of web2py are you using. What is the controller in question?

[c...@cemeren.com]

Since you mentioned that the server stalls either, could it be possible that your error handler is creating another error and causing an infinite loop? If you check that request.vars.request_url does not equal to request.url, this could be prevented. I admit that it is just a guess of mine with good intention.

[Louis Amon]

@Niphlod:

I've simplified my error handler as far as this :

No models, controller has 2 lines :

def index():
    return dict()

The result is still the same : web2py stalling forever, no page displayed.

@Derek:

I'm developping on a MacOSX computer but my server is hosted on Heroku (probably some kind of Linux distribution) : the problem is the same on both environments.

I can't make my server run locally on any other server than rocket right now (and never had to so far). I'll have to look into that if the problem persists.

@Massimo:

I'm using this version:

2.9.11-stable+timestamp.2014.09.15.23.35.11
(Running on Rocket 1.2.6, Python 2.7.9)

The controller in question is just some error handler I made that automatically (and synchroneously) sends tickets as e-mails to administrators. This is due to Heroku having an ephemeral filesystem : you can't rely on tickets being stored on the filesystem for any length of time.

@cem:

The controller I built was based on this slice, so it has the 2 lines that should prevent an infinite error loop :

if code is not None and request_url != request.url:	# Make sure error url is not current url to avoid infinite loop.
		response.status = int(code) # Assign the error status code to the current response. (Must be integer to work.)

[c...@cemeren.com]

Anyone, willing to support you, might need your error routing code to help you more, as you wrote that the built-in ticket system works just fine.

13 Ocak 2015 Salı 19:29:28 UTC+2 tarihinde Louis Amon yazdı:

[Louis Amon]

I've provided 2 files attached to this reply : one simple app and a routes.py file to reroute errors to said app.

It's exactly as described in this recipe : http://www.web2pyslices.com/slice/show/1529/custom-error-routing

Now if you install this app and apply the routes, you can go to this URL : http://127.0.0.1:8000/routes_error_test and see a very simple form.

If you submit the form, Rocket will display a "HTTP: 400 BAD REQUEST" exception.

I've tested this with a clone from the official web2py Git.

Can anyone replicate this ?