internal error trying to serve HEAD

[John A Meinel]

root: 91.189.90.11 - - [10/Mar/2011:10:08:32 +0000] "HEAD /%7Evcs-imports/busybox/main/changes HTTP/1.0" 200 - "-" "-"
INF [20110310-10:08:32.545] [47191873160960] loggerhead: Processed ok http://0.0.0.0:8080/%7Evcs-imports/busybox/main/changes [0.440 seconds]
ERR [20110310-10:08:32.546] [47191873160960] root: Traceback (most recent call last):
ERR [20110310-10:08:32.546] [47191873160960] root: File "/srv/codebrowse.launchpad.net/production/launchpad-rev-12559/eggs/Paste-1.7.2-py2.6.egg/paste/httpserver.py", line 1062, in process_request_in_thread
ERR [20110310-10:08:32.546] [47191873160960] root: self.finish_request(request, client_address)
ERR [20110310-10:08:32.546] [47191873160960] root: File "/usr/lib/python2.6/SocketServer.py", line 320, in finish_request
ERR [20110310-10:08:32.546] [47191873160960] root: self.RequestHandlerClass(request, client_address, self)
ERR [20110310-10:08:32.546] [47191873160960] root: File "/usr/lib/python2.6/SocketServer.py", line 615, in __init__
ERR [20110310-10:08:32.546] [47191873160960] root: self.handle()
ERR [20110310-10:08:32.547] [47191873160960] root: File "/srv/codebrowse.launchpad.net/production/launchpad-rev-12559/eggs/Paste-1.7.2-py2.6.egg/paste/httpserver.py", line 436, in handle
ERR [20110310-10:08:32.547] [47191873160960] root: BaseHTTPRequestHandler.handle(self)
ERR [20110310-10:08:32.547] [47191873160960] root: File "/usr/lib/python2.6/BaseHTTPServer.py", line 329, in handle
ERR [20110310-10:08:32.547] [47191873160960] root: self.handle_one_request()
ERR [20110310-10:08:32.547] [47191873160960] root: File "/srv/codebrowse.launchpad.net/production/launchpad-rev-12559/eggs/Paste-1.7.2-py2.6.egg/paste/httpserver.py", line 431, in handle_one_request
ERR [20110310-10:08:32.547] [47191873160960] root: self.wsgi_execute()
ERR [20110310-10:08:32.547] [47191873160960] root: File "/srv/codebrowse.launchpad.net/production/launchpad-rev-12559/eggs/Paste-1.7.2-py2.6.egg/paste/httpserver.py", line 292, in wsgi_execute
ERR [20110310-10:08:32.547] [47191873160960] root: self.wsgi_write_chunk('')
ERR [20110310-10:08:32.547] [47191873160960] root: File "/srv/codebrowse.launchpad.net/production/launchpad-rev-12559/eggs/Paste-1.7.2-py2.6.egg/paste/httpserver.py", line 125, in wsgi_write_chunk
ERR [20110310-10:08:32.547] [47191873160960] root: "Content returned before start_response called")
ERR [20110310-10:08:32.547] [47191873160960] root: RuntimeError: Content returned before start_response called

[John A Meinel (jameinel)]

The first thing that strikes me, is that all of the code is in Paste and Wsgilib, etc. There isn't any Launchpad code here.

My best guess is that we got an exception while processing an exception? Still trying to dig into it.

[John A Meinel (jameinel)]

I can reproduce this locally with the Launchpad. Using:
HEAD http://bazaar.launchpad.dev:8080/~jameinel/+junk/foo/changes

However, I *don't* see this when running Loggerhead using "bzr serve --http". Though that is also using the system wide Paste and simpletal. Tracking it down further.

[John A Meinel (jameinel)]

This is also seen when using 'bin/py' from launchpad, and using SIGQUIT to confirm what dependencies are being used. So it looks to be strictly a bug in the Launchpad glue binding around Loggerhead.

[John A Meinel (jameinel)]

I think I've isolated the bug, and we just need a bit more direct tests.

The issue is that WrappedStartResponse delays the actual call to start_response() until after stuff has been processed. (Presumably so that it can send an OOPS page if it gets an error from the time start_response is called, to the point where content actually starts streaming.)

However, if the app doesn't return any content, then this is the loop:
           while True:
                try:
                    data = app_iter.next()
                except StopIteration:
                    return
                if not wrapped.body_started:
                    wrapped.really_start()
                yield data

This happened when I consolidated the code paths between the various try/except OOPS logic. (Though it might have had the bug as well).

We didn't notice until this deployment, because loggerhead was still generating body content for HEAD. Once we started deploying the new loggerhead (this release), it stopped generating body content, so this check broke.

One option is to add a try/finally to make sure that wrapped.really_start() is always called if start_response has been called. I'll poke at it a bit to make sure things look decent, and I'll try to add some paste interactions to make sure we catch this.

[John A Meinel (jameinel)]

Not actually a bug in loggerhead. We ran into this because of deploying a loggerhead that stopped writing BODY content for a HEAD request, which exposed a bug in our oops_middleware logic when there is no BODY content.

[Launchpad QA Bot (lpqabot)]

Fixed in stable r12583 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/12583>.

[John A Meinel (jameinel)]

Can't qa this because Loggerhead doesn't run correctly on qastaging. :(

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 3/15/2011 1:01 AM, Robert Collins wrote:
> ** Changed in: launchpad
> Status: Fix Committed => Fix Released
>

Confirmed. Just sent a HEAD request to
http://bazaar.launchpad.net/~jameinel/bzr/integration/changes

And it came back HTTP 200 OK instead of HTTP 500 Internal Server Error.

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk1/R7MACgkQJdeBCYSNAAPhZACeMnrd4ae2j0jMrYM8N3mRHY04
EGAAnjhRdCNIEnmCFrhfcib284K4DiEQ
=1KBy
-----END PGP SIGNATURE-----