Open GoogleCodeExporter opened 9 years ago
I'm noticing this on a backend which does hundreds of async urlfetch requests.
Original comment by pdknsk
on 12 Feb 2013 at 12:27
I can confirm that I do a lot of urlfetch requests. Synchronously, mind you.
Original comment by brianmh...@gmail.com
on 12 Feb 2013 at 1:32
This doesn't seem to be related to urlfetch (or anything really). I can notice
this occurring sporadically on a handler that just sleeps for 100 seconds. What
seems safe to say is that the error is more likely to occur with increasing
request time.
Original comment by pdknsk
on 21 Feb 2013 at 7:18
Could you retest this with the 0.7 release?
Original comment by bquin...@google.com
on 25 Feb 2013 at 5:20
I just tried, it's the same. The same code on frontends works fine.
Original comment by pdknsk
on 25 Feb 2013 at 10:54
This issue no longer seems to occurs for me.
That being said, I have also changed to Python 2.7.3 via homebrew, from the
native version of Python on the Mac. Homebrew's python could have fixed the
underlying problem for me.
I will be certain to report if I encounter the issue again (here, or if this
issue is closed I will reference this).
Original comment by brianmh...@gmail.com
on 25 Feb 2013 at 8:18
I cannot reproduce this in 0.8 so it's probably fixed.
Original comment by pdknsk
on 12 Mar 2013 at 6:57
Literally seconds after I wrote this, it occurred again, after working for
quite a while before.
Original comment by pdknsk
on 12 Mar 2013 at 6:59
I'm getting a somewhat different stack trace, so maybe it's not for the same
reason.
BadStatusLine("''",)
Traceback (most recent call last):
File "/home/user/appengine/d2/lib/cherrypy/cherrypy/wsgiserver/wsgiserver2.py", line 1302, in communicate
req.respond()
File "/home/user/appengine/d2/lib/cherrypy/cherrypy/wsgiserver/wsgiserver2.py", line 831, in respond
self.server.gateway(self).respond()
File "/home/user/appengine/d2/lib/cherrypy/cherrypy/wsgiserver/wsgiserver2.py", line 2115, in respond
response = self.req.server.wsgi_app(self.env, self.start_response)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/wsgi_server.py", line 245, in __call__
return app(environ, start_response)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/server.py", line 2091, in __call__
return self._handle_request(environ, start_response, inst)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/server.py", line 601, in _handle_request
environ, wrapped_start_response)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/request_rewriter.py", line 311, in _rewriter_middleware
response_body = iter(application(environ, wrapped_start_response))
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/server.py", line 1934, in _handle_script_request
request_id, request_type)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/instance.py", line 382, in handle
request_type))
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/http_runtime.py", line 147, in handle
response = connection.getresponse()
File "/usr/lib/python2.7/httplib.py", line 1034, in getresponse
response.begin()
File "/usr/lib/python2.7/httplib.py", line 407, in begin
version, status, reason = self._read_status()
File "/usr/lib/python2.7/httplib.py", line 371, in _read_status
raise BadStatusLine(line)
BadStatusLine: ''
Original comment by pdknsk
on 12 Mar 2013 at 7:01
Could you try again with --dev_appserver_log_level=debug and send me the output?
Original comment by bquin...@google.com
on 13 Mar 2013 at 11:05
This is the full request log of a handler on '/' that just sleeps for 100
seconds.
DEBUG 2013-03-14 15:26:53,706 appengine_rpc.py:174] Server:
appengine.google.com
INFO 2013-03-14 15:26:53,721 sdk_update_checker.py:244] Checking for
updates to the SDK.
DEBUG 2013-03-14 15:26:53,723 appengine_rpc.py:392] Sending HTTPS request:
POST
/api/updatecheck?api_versions=%5B%271%27%5D&release=1.7.6&runtime=python27×tamp
=1360882848 HTTPS/1.1
Host: appengine.google.com
X-appcfg-api-version: 1
Content-type: application/octet-stream
User-agent: devappserver2_py/1.7.6 Linux/3.5.0-25-generic Python/2.7.3.final.0
INFO 2013-03-14 15:26:53,991 sdk_update_checker.py:288] This SDK release is
newer than the advertised release.
INFO 2013-03-14 15:26:54,037 api_server.py:152] Starting API server at:
http://localhost:57727
DEBUG 2013-03-14 15:26:54,062 inotify_file_watcher.py:97]
_add_watch_for_path('/home/user/appengine/k/be')
INFO 2013-03-14 15:26:54,064 dispatcher.py:150] Starting server "be"
running at: http://localhost:8080
INFO 2013-03-14 15:26:54,066 admin_server.py:117] Starting admin server at:
http://localhost:8000
DEBUG 2013-03-14 15:26:56,633 instance.py:278] Started instance: <Instance
0: 0/8, total: 0 [handling ready request]>
DEBUG 2013-03-14 15:26:56,634 server.py:1972] Started instance: <Instance 0:
0/8, total: 0 [handling ready request]> at http://localhost:52972
DEBUG 2013-03-14 15:26:56,637 server.py:1862] Dispatching request to
<Instance 0: 0/8, total: 0 [handling ready request]> after 0.0000s pending
DEBUG 2013-03-14 15:26:57,414 api_server.py:191] Handled logservice.Flush in
0.0013
DEBUG 2013-03-14 15:26:57,421 instance.py:385] Request handled by <Instance
0: 1/8, total: 1 [handling ready request]> in 0.7829s
DEBUG 2013-03-14 15:26:57,422 server.py:1932] Dispatching request to
<Instance 0: 0/8, total: 1> after 1.6488s pending
INFO 2013-03-14 15:26:57,427 server.py:559] be: "GET /_ah/start HTTP/1.1"
404 -
DEBUG 2013-03-14 15:26:57,427 server.py:1981] Sent start request: <Instance
0: 1/8, total: 2>
DEBUG 2013-03-14 15:26:58,071 inotify_file_watcher.py:176] wd=1, mask=0x200,
cookie=0, length=16, name='main.pyc'
DEBUG 2013-03-14 15:26:58,072 inotify_file_watcher.py:176] wd=1, mask=0x100,
cookie=0, length=16, name='main.pyc'
DEBUG 2013-03-14 15:26:58,072 inotify_file_watcher.py:176] wd=1, mask=0x2,
cookie=0, length=16, name='main.pyc'
DEBUG 2013-03-14 15:26:58,087 server.py:1862] Dispatching request to
<Instance 0: 1/8, total: 2> after 0.0000s pending
DEBUG 2013-03-14 15:26:58,107 api_server.py:191] Handled logservice.Flush in
0.0005
DEBUG 2013-03-14 15:26:58,112 instance.py:385] Request handled by <Instance
0: 1/8, total: 3> in 0.0229s
INFO 2013-03-14 15:26:58,116 server.py:559] be: "GET /_ah/stop HTTP/1.1"
200 -
DEBUG 2013-03-14 15:26:58,116 server.py:623] Sent shutdown request:
<Instance 0: 1/8, total: 3 [quitting]>
DEBUG 2013-03-14 15:26:58,975 instance.py:278] Started instance: <Instance
0: 0/8, total: 0 [handling ready request]>
DEBUG 2013-03-14 15:26:58,975 server.py:1972] Started instance: <Instance 0:
0/8, total: 0 [handling ready request]> at http://localhost:52972
DEBUG 2013-03-14 15:26:58,977 server.py:1862] Dispatching request to
<Instance 0: 0/8, total: 0 [handling ready request]> after 0.0000s pending
DEBUG 2013-03-14 15:26:59,779 api_server.py:191] Handled logservice.Flush in
0.0108
DEBUG 2013-03-14 15:26:59,785 instance.py:385] Request handled by <Instance
0: 1/8, total: 1 [handling ready request]> in 0.8072s
INFO 2013-03-14 15:26:59,787 server.py:559] be: "GET /_ah/start HTTP/1.1"
404 -
DEBUG 2013-03-14 15:26:59,788 server.py:1981] Sent start request: <Instance
0: 0/8, total: 1>
DEBUG 2013-03-14 15:27:28,079 instance.py:315] Quit instance: <Instance 0:
1/8, total: 3 [quitting quit]>
DEBUG 2013-03-14 15:27:28,088 instance.py:385] Request handled by <Instance
0: 1/8, total: 3 [quitting quit]> in 30.6659s
BadStatusLine("''",)
Traceback (most recent call last):
File "/home/user/appengine/d2/lib/cherrypy/cherrypy/wsgiserver/wsgiserver2.py", line 1302, in communicate
req.respond()
File "/home/user/appengine/d2/lib/cherrypy/cherrypy/wsgiserver/wsgiserver2.py", line 831, in respond
self.server.gateway(self).respond()
File "/home/user/appengine/d2/lib/cherrypy/cherrypy/wsgiserver/wsgiserver2.py", line 2115, in respond
response = self.req.server.wsgi_app(self.env, self.start_response)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/wsgi_server.py", line 245, in __call__
return app(environ, start_response)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/server.py", line 2091, in __call__
return self._handle_request(environ, start_response, inst)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/server.py", line 601, in _handle_request
environ, wrapped_start_response)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/request_rewriter.py", line 311, in _rewriter_middleware
response_body = iter(application(environ, wrapped_start_response))
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/server.py", line 1934, in _handle_script_request
request_id, request_type)
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/instance.py", line 382, in handle
request_type))
File "/home/user/appengine/d2/google/appengine/tools/devappserver2/http_runtime.py", line 147, in handle
response = connection.getresponse()
File "/usr/lib/python2.7/httplib.py", line 1034, in getresponse
response.begin()
File "/usr/lib/python2.7/httplib.py", line 407, in begin
version, status, reason = self._read_status()
File "/usr/lib/python2.7/httplib.py", line 371, in _read_status
raise BadStatusLine(line)
BadStatusLine: ''
Original comment by pdknsk
on 14 Mar 2013 at 3:35
I don't know if this issue has been worked on, but in 1.7.7 it still occurs.
Original comment by pdknsk
on 3 Apr 2013 at 3:19
Why can't I +1 this instead of starring it?
This issue happens all the time for me as well
Original comment by s...@blinkfire.com
on 18 May 2013 at 11:21
I see this on a more or less daily basis
Original comment by o...@humblebundle.com
on 28 May 2013 at 6:42
I have code that can reproduce this issue almost exactly 50% of the time. The
code involves backend instances (called from a frontend instance via urlfetch)
doing a lot of writing to the datastore, if that matters.
Recently this issue has been significantly impeding my workflow.
Original comment by a...@humblebundle.com
on 28 May 2013 at 6:46
This issue tracker appears abandoned. I've filed a new issue. I also just
noticed that my comment from March 14 with the full debug log is deleted. I
cannot undelete it. Maybe it is automatically deleted because of length.
https://code.google.com/p/googleappengine/issues/detail?id=9399
Original comment by pdknsk
on 28 May 2013 at 7:20
Original issue reported on code.google.com by
brianmh...@gmail.com
on 8 Feb 2013 at 9:26