Bug 107184 - HTTP 500 error between QueueStatusServer and bot(s)
Summary: HTTP 500 error between QueueStatusServer and bot(s)
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Tools / Tests (show other bugs)
Version: 528+ (Nightly build)
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Alan Cutter
URL:
Keywords:
: 75024 107388 (view as bug list)
Depends on:
Blocks:
 
Reported: 2013-01-17 14:57 PST by Alan Cutter
Modified: 2013-01-30 21:19 PST (History)
5 users (show)

See Also:


Attachments
Patch (2.09 KB, patch)
2013-01-24 22:02 PST, Alan Cutter
no flags Details | Formatted Diff | Diff
Patch (2.88 KB, patch)
2013-01-24 22:11 PST, Alan Cutter
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Alan Cutter 2013-01-17 14:57:43 PST
The feeder queue is frequently blocked for over 8 minutes at a time.

feeder-queue logs:

> Feeding commit-queue items [182076, 183087]
> Feeding EWS (551 r? patches, 14 new)
> Submitting attachment 124896 [details] to EWS queues
> Submitting attachment 183107 [details] to EWS queues
> Submitting attachment 179684 [details] to EWS queues
> Submitting attachment 183109 [details] to EWS queues
> Submitting attachment 158695 [details] to EWS queues
> Submitting attachment 120296 [details] to EWS queues
> Submitting attachment 182256 [details] to EWS queues
> Submitting attachment 157608 [details] to EWS queues
> Submitting attachment 179699 [details] to EWS queues
> Submitting attachment 177748 [details] to EWS queues
> Submitting attachment 158718 [details] to EWS queues
> Submitting attachment 167385 [details] to EWS queues
> Received HTTP status 500 loading "None".  Retrying in 10 seconds...
> Received HTTP status 500 loading "None".  Retrying in 15.0 seconds...
> Received HTTP status 500 loading "None".  Retrying in 22.5 seconds...
> Received HTTP status 500 loading "None".  Retrying in 33.75 seconds...
> Received HTTP status 500 loading "None".  Retrying in 50.625 seconds...
> Received HTTP status 500 loading "None".  Retrying in 75.9375 seconds...
> Received HTTP status 500 loading "None".  Retrying in 113.90625 seconds...
> Received HTTP status 500 loading "None".  Retrying in 170.859375 seconds...
> Traceback (most recent call last):
>   File "/mnt/git/webkit-feeder-queue/Tools/Scripts/webkitpy/tool/bot/queueengine.py", line 105, in run
>     if not self._delegate.process_work_item(work_item):
>   File "/mnt/git/webkit-feeder-queue/Tools/Scripts/webkitpy/tool/commands/queues.py", line 196, in process_work_item
>     feeder.feed()
>   File "/mnt/git/webkit-feeder-queue/Tools/Scripts/webkitpy/tool/bot/feeders.py", line 97, in feed
>     self._tool.status_server.submit_to_ews(attachment_id)
>   File "/mnt/git/webkit-feeder-queue/Tools/Scripts/webkitpy/common/net/statusserver.py", line 123, in submit_to_ews
>     return NetworkTransaction().run(lambda: self._post_work_item_to_ews(attachment_id))
>   File "/mnt/git/webkit-feeder-queue/Tools/Scripts/webkitpy/common/net/networktransaction.py", line 57, in run
>     self._check_for_timeout()
>   File "/mnt/git/webkit-feeder-queue/Tools/Scripts/webkitpy/common/net/networktransaction.py", line 63, in _check_for_timeout
>     raise NetworkTimeout()
> NetworkTimeout: NetworkTimeout
> Exception while preparing queue Sleeping until 2013-01-17 04:52:19 (2 mins).


The QueueStatusServer frequently throws HTTP 500 errors.

QSS logs:

Recent errors:

> 2013-01-16 21:21:35.024 /submit-to-ews 500 750ms 2kb Python-urllib/2.6
> E 2013-01-16 21:21:35.017 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:18:43.200 /submit-to-ews 500 517ms 2kb Python-urllib/2.6
> E 2013-01-16 21:18:43.197 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:16:48.409 /submit-to-ews 500 416ms 2kb Python-urllib/2.6
> E 2013-01-16 21:16:48.394 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:15:31.652 /submit-to-ews 500 493ms 2kb Python-urllib/2.6
> E 2013-01-16 21:15:31.650 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:14:40.224 /submit-to-ews 500 1150ms 2kb Python-urllib/2.6
> E 2013-01-16 21:14:40.218 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:14:04.705 /submit-to-ews 500 327ms 2kb Python-urllib/2.6
> E 2013-01-16 21:14:04.703 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:13:41.396 /submit-to-ews 500 464ms 2kb Python-urllib/2.6
> E 2013-01-16 21:13:41.394 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:13:25.793 /submit-to-ews 500 327ms 2kb Python-urllib/2.6
> E 2013-01-16 21:13:25.790 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:13:15.324 /submit-to-ews 500 391ms 2kb Python-urllib/2.6
> E 2013-01-16 21:13:15.322 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:11:09.632 /submit-to-ews 500 1127ms 2kb Python-urllib/2.6
> E 2013-01-16 21:11:09.619 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:08:17.301 /submit-to-ews 500 853ms 2kb Python-urllib/2.6
> E 2013-01-16 21:08:17.299 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:06:22.207 /submit-to-ews 500 347ms 2kb Python-urllib/2.6
> E 2013-01-16 21:06:22.205 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:05:05.513 /submit-to-ews 500 512ms 2kb Python-urllib/2.6
> E 2013-01-16 21:05:05.512 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:04:13.935 /submit-to-ews 500 312ms 2kb Python-urllib/2.6
> E 2013-01-16 21:04:13.933 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:03:39.489 /submit-to-ews 500 708ms 2kb Python-urllib/2.6
> E 2013-01-16 21:03:39.487 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib
> 2013-01-16 21:03:16.167 /submit-to-ews 500 717ms 2kb Python-urllib/2.6
> E 2013-01-16 21:03:16.159 Values may not be more than 1000000 bytes in length; received 1054167 bytes Traceback (most recent call last): File "/base/python_runtime/python_lib


Single error detail:

> 2013-01-16 21:15:31.652 /submit-to-ews 500 493ms 2kb Python-urllib/2.6
> 8.34.213.203 - - [16/Jan/2013:21:15:31 -0800] "POST /submit-to-ews HTTP/1.1" 500 2132 "http://queues.webkit.org/submit-to-ews" "Python-urllib/2.6" "queues.webkit.org" ms=493 cpu_ms=107 cpm_usd=0.000238 instance=00c61b117c8dc6bb676ce419546a20bc69ae89
> E 2013-01-16 21:15:31.650
> Values may not be more than 1000000 bytes in length; received 1054167 bytes
> Traceback (most recent call last):
>   File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/webapp/_webapp25.py", line 716, in __call__
>     handler.post(*groups)
>   File "/base/data/home/apps/webkit-commit-queue/1.364503684603662849/handlers/submittoews.py", line 64, in post
>     self._add_attachment_to_ews_queues(attachment)
>   File "/base/data/home/apps/webkit-commit-queue/1.364503684603662849/handlers/submittoews.py", line 58, in _add_attachment_to_ews_queues
>     if self._should_add_to_ews_queue(queue, attachment):
>   File "/base/data/home/apps/webkit-commit-queue/1.364503684603662849/handlers/submittoews.py", line 46, in _should_add_to_ews_queue
>     latest_status = attachment.status_for_queue(queue)
>   File "/base/data/home/apps/webkit-commit-queue/1.364503684603662849/model/attachment.py", line 95, in status_for_queue
>     queue_summary = self.summary().get(queue.name_with_underscores())
>   File "/base/data/home/apps/webkit-commit-queue/1.364503684603662849/model/attachment.py", line 73, in summary
>     memcache.set(str(self.id), self._summary, namespace="attachment-summary")
>   File "/base/python_runtime/python_lib/versions/1/google/appengine/api/memcache/__init__.py", line 793, in set
>     namespace=namespace)
>   File "/base/python_runtime/python_lib/versions/1/google/appengine/api/memcache/__init__.py", line 898, in _set_with_policy
>     time, '', namespace)
>   File "/base/python_runtime/python_lib/versions/1/google/appengine/api/memcache/__init__.py", line 977, in _set_multi_async_with_policy
>     stored_value, flags = _validate_encode_value(value, self._do_pickle)
>   File "/base/python_runtime/python_lib/versions/1/google/appengine/api/memcache/__init__.py", line 236, in _validate_encode_value
>     'received %d bytes' % (MAX_VALUE_SIZE, len(stored_value)))
> ValueError: Values may not be more than 1000000 bytes in length; received 1054167 bytes



These are probably related and may account for the unusual consistently spiky requests/s graph in App Engine.
Comment 1 Adam Barth 2013-01-17 16:14:23 PST
Which value is getting too big?  We've seen this in the past when there's a queue that hasn't been processing for a long time and has lots of work to do...
Comment 2 Philip Rogers 2013-01-19 18:55:06 PST
*** Bug 107388 has been marked as a duplicate of this bug. ***
Comment 3 Alan Cutter 2013-01-24 22:02:57 PST
Created attachment 184662 [details]
Patch
Comment 4 Alan Cutter 2013-01-24 22:05:47 PST
(In reply to comment #3)
> Created an attachment (id=184662) [details]
> Patch

Patch removes the use of memcache from the Attachment class.
Comment 5 Adam Barth 2013-01-24 22:05:49 PST
Comment on attachment 184662 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=184662&action=review

> Tools/QueueStatusServer/model/attachment.py:-41
> -    def dirty(cls, attachment_id):
> -        memcache.delete(str(attachment_id), namespace="attachment-summary")

Don't we need to remove the caller of this function in updatestate.py?
Comment 6 Alan Cutter 2013-01-24 22:11:26 PST
Created attachment 184664 [details]
Patch
Comment 7 Alan Cutter 2013-01-24 22:12:21 PST
(In reply to comment #5)
> (From update of attachment 184662 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=184662&action=review
> 
> > Tools/QueueStatusServer/model/attachment.py:-41
> > -    def dirty(cls, attachment_id):
> > -        memcache.delete(str(attachment_id), namespace="attachment-summary")
> 
> Don't we need to remove the caller of this function in updatestate.py?

Thanks for catching that, removed all calls to Attachment.dirty().
Comment 8 Eric Seidel (no email) 2013-01-24 22:53:15 PST
Comment on attachment 184664 [details]
Patch

This is OK.  Presumably we'll have to implement a replacement for what we were attempting to cache. :)
Comment 9 WebKit Review Bot 2013-01-24 22:56:40 PST
Comment on attachment 184664 [details]
Patch

Rejecting attachment 184664 [details] from commit-queue.

Failed to run "['/mnt/git/webkit-commit-queue/Tools/Scripts/webkit-patch', '--status-host=queues.webkit.org', '--bot-id=gce-cq-02', 'apply-attachment', '--no-update', '--non-interactive', 184664, '--port=chromium-xvfb']" exit_code: 2 cwd: /mnt/git/webkit-commit-queue

Last 500 characters of output:
ply', '--force', '--reviewer', 'Adam Barth']" exit_code: 2 cwd: /mnt/git/webkit-commit-queue

Parsed 3 diffs from patch file(s).
patch: **** Can't create file /tmp/ppCBCh5i : No space left on device
patch: **** Can't create file /tmp/ppBG1Tdm : No space left on device
patch: **** Can't create file /tmp/ppMfF0Ml : No space left on device

Failed to run "[u'/mnt/git/webkit-commit-queue/Tools/Scripts/svn-apply', '--force', '--reviewer', 'Adam Barth']" exit_code: 2 cwd: /mnt/git/webkit-commit-queue

Full output: http://queues.webkit.org/results/16120144
Comment 10 Adam Barth 2013-01-24 23:01:31 PST
Comment on attachment 184664 [details]
Patch

Clearing flags on attachment: 184664

Committed r140786: <http://trac.webkit.org/changeset/140786>
Comment 11 Adam Barth 2013-01-24 23:01:35 PST
All reviewed patches have been landed.  Closing bug.
Comment 12 Alan Cutter 2013-01-30 21:19:42 PST
*** Bug 75024 has been marked as a duplicate of this bug. ***