python job failure randomly

[Feilong Wang]

This test case zaqar.tests.unit.transport.websocket.v2.test_claims.ClaimsBaseTest.test_lifecycle fails randomly with below log:

2016-05-16 02:57:08.800 | Stage <zaqar.storage.mongodb.messages.MessageQueueHandler object at 0x7f62604d2550> does not implement create
2016-05-16 02:57:08.843 | Stage <zaqar.storage.mongodb.messages.MessageQueueHandler object at 0x7f62603f3990> does not implement list
2016-05-16 02:57:10.027 | running=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
2016-05-16 02:57:10.027 | OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
2016-05-16 02:57:10.027 | OS_TEST_TIMEOUT=${OS_TEST_TIMEOUT:-60} \
2016-05-16 02:57:10.027 | ${PYTHON:-python} $JIT_FLAG -m subunit.run discover -t ${OS_TOP_LEVEL:-./} ${OS_TEST_PATH:-./zaqar/tests/unit}
2016-05-16 02:57:10.027 | ======================================================================
2016-05-16 02:57:10.027 | FAIL: zaqar.tests.unit.transport.websocket.v2.test_claims.ClaimsBaseTest.test_lifecycle
2016-05-16 02:57:10.027 | tags: worker-0
2016-05-16 02:57:10.027 | ----------------------------------------------------------------------
2016-05-16 02:57:10.027 | Empty attachments:
2016-05-16 02:57:10.027 | stdout
2016-05-16 02:57:10.028 |
2016-05-16 02:57:10.028 | pythonlogging:'zaqar': {{{
2016-05-16 02:57:10.028 | Stage <zaqar.storage.mongodb.messages.MessageQueueHandler object at 0x7f6240791e50> does not implement create
2016-05-16 02:57:10.028 | Response: API v2 txt, 201. Request: action "queue_create", body {"queue_name": "skittle"}.
2016-05-16 02:57:10.028 | Stage <zaqar.storage.mongodb.messages.MessageQueueHandler object at 0x7f6240791e50> does not implement get_metadata
2016-05-16 02:57:10.028 | Response: API v2 txt, 201. Request: action "message_post", body {"queue_name": "skittle", "messages": [{"body": 239, "ttl": 300}, {"body": {"key_1": "value_1"}, "ttl": 300}, {"body": [1, 3], "ttl": 300}, {"body": 439, "ttl": 300}, {"body": {"key_2": "value_2"}, "ttl": 300}, {"body": ["a", "b"], "ttl": 300}, {"body": 639, "ttl": 300}, {"body": {"key_3": "value_3"}, "ttl": 300}, {"body": ["aa", "bb"], "ttl": 300}]}.
2016-05-16 02:57:10.028 | Response: API v2 txt, 201. Request: action "claim_create", body {"ttl": 100, "queue_name": "skittle", "grace": 60}.
2016-05-16 02:57:10.028 | Response: API v2 txt, 204. Request: action "claim_create", body {"ttl": 100, "queue_name": "skittle", "grace": 60}.
2016-05-16 02:57:10.028 | Response: API v2 txt, 200. Request: action "message_list", body {"queue_name": "skittle", "echo": true}.
2016-05-16 02:57:10.028 | Response: API v2 txt, 200. Request: action "message_list", body {"queue_name": "skittle", "echo": false}.
2016-05-16 02:57:10.028 | Response: API v2 txt, 200. Request: action "message_list", body {"include_claimed": true, "queue_name": "skittle", "echo": false}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 200. Request: action "message_list", body {"queue_name": "skittle", "echo": false}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 200. Request: action "message_list", body {"include_claimed": true, "queue_name": "skittle", "echo": true}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 403. Request: action "message_delete", body {"message_id": "573937059027491ba4231b5b", "queue_name": "skittle"}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 204. Request: action "message_delete", body {"message_id": "573937059027491ba4231b5b", "queue_name": "skittle", "claim_id": "573937059027491ba4231b64"}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 404. Request: action "message_get", body {"message_id": "573937059027491ba4231b5c", "queue_name": "skittle"}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 200. Request: action "message_get", body {"message_id": "573937059027491ba4231b5c", "queue_name": "skittle"}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 204. Request: action "claim_update", body {"ttl": 60, "queue_name": "skittle", "claim_id": "573937059027491ba4231b64", "grace": 60}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 200. Request: action "claim_get", body {"queue_name": "skittle", "claim_id": "573937059027491ba4231b64"}.
2016-05-16 02:57:10.029 | Response: API v2 txt, 204. Request: action "queue_delete", body {"queue_name": "skittle"}.
2016-05-16 02:57:10.029 | }}}
2016-05-16 02:57:10.029 |
2016-05-16 02:57:10.029 | stderr: {{{
2016-05-16 02:57:10.030 | 2016-05-16 02:57:09.974 7076 WARNING zaqar.common.pipeline [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Stage <zaqar.storage.mongodb.messages.MessageQueueHandler object at 0x7f6240791e50> does not implement create
2016-05-16 02:57:10.030 | 2016-05-16 02:57:09.976 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 201. Request: action "queue_create", body {"queue_name": "skittle"}.
2016-05-16 02:57:10.030 | 2016-05-16 02:57:09.977 7076 WARNING zaqar.common.pipeline [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Stage <zaqar.storage.mongodb.messages.MessageQueueHandler object at 0x7f6240791e50> does not implement get_metadata
2016-05-16 03:01:04.742 | 2016-05-16 02:57:09.981 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 201. Request: action "message_post", body {"queue_name": "skittle", "messages": [{"body": 239, "ttl": 300}, {"body": {"key_1": "value_1"}, "ttl": 300}, {"body": [1, 3], "ttl": 300}, {"body": 439, "ttl": 300}, {"body": {"key_2": "value_2"}, "ttl": 300}, {"body": ["a", "b"], "ttl": 300}, {"body": 639, "ttl": 300}, {"body": {"key_3": "value_3"}, "ttl": 300}, {"body": ["aa", "bb"], "ttl": 300}]}.
2016-05-16 03:01:04.742 | 2016-05-16 02:57:09.985 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 201. Request: action "claim_create", body {"ttl": 100, "queue_name": "skittle", "grace": 60}.
2016-05-16 03:01:04.742 | 2016-05-16 02:57:09.986 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 204. Request: action "claim_create", body {"ttl": 100, "queue_name": "skittle", "grace": 60}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.987 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "message_list", body {"queue_name": "skittle", "echo": true}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.989 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "message_list", body {"queue_name": "skittle", "echo": false}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.990 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "message_list", body {"include_claimed": true, "queue_name": "skittle", "echo": false}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.992 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "message_list", body {"queue_name": "skittle", "echo": false}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.993 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "message_list", body {"include_claimed": true, "queue_name": "skittle", "echo": true}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.994 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 403. Request: action "message_delete", body {"message_id": "573937059027491ba4231b5b", "queue_name": "skittle"}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.996 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 204. Request: action "message_delete", body {"message_id": "573937059027491ba4231b5b", "queue_name": "skittle", "claim_id": "573937059027491ba4231b64"}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.997 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 404. Request: action "message_get", body {"message_id": "573937059027491ba4231b5c", "queue_name": "skittle"}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:09.998 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "message_get", body {"message_id": "573937059027491ba4231b5c", "queue_name": "skittle"}.
2016-05-16 03:01:04.743 | 2016-05-16 02:57:10.000 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 204. Request: action "claim_update", body {"ttl": 60, "queue_name": "skittle", "claim_id": "573937059027491ba4231b64", "grace": 60}.
2016-05-16 03:01:04.744 | 2016-05-16 02:57:10.001 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 200. Request: action "claim_get", body {"queue_name": "skittle", "claim_id": "573937059027491ba4231b64"}.
2016-05-16 03:01:04.744 | 2016-05-16 02:57:10.004 7076 INFO zaqar.transport.websocket.protocol [req-c5573506-743a-4c06-a014-7dd2bca8fa7e - - - - -] Response: API v2 txt, 204. Request: action "queue_delete", body {"queue_name": "skittle"}.
2016-05-16 03:01:04.744 | }}}
2016-05-16 03:01:04.744 |
2016-05-16 03:01:04.744 | Traceback (most recent call last):
2016-05-16 03:01:04.744 | File "zaqar/tests/unit/transport/websocket/v2/test_claims.py", line 342, in test_lifecycle
2016-05-16 03:01:04.744 | self.assertTrue(estimated_age > resp['body']['age'])
2016-05-16 03:01:04.744 | File "/home/jenkins/workspace/gate-zaqar-python27/.tox/py27/local/lib/python2.7/site-packages/unittest2/case.py", line 702, in assertTrue
2016-05-16 03:01:04.744 | raise self.failureException(msg)
2016-05-16 03:01:04.744 | AssertionError: False is not true
2016-05-16 03:01:04.744 | Ran 990 tests in 412.013s
2016-05-16 03:01:04.745 | FAILED (id=0, failures=1, skips=9)
2016-05-16 03:01:04.745 | error: testr failed (1)
2016-05-16 03:01:04.854 | ERROR: InvocationError: '/home/jenkins/workspace/gate-zaqar-python27/.tox/py27/bin/python setup.py testr --slowest --testr-args=--concurrency 1 '