[zmq] zmq_ack_manager test failure on ubuntu trusty

[Oleksii Zamiatin]

Time after time get failure on Ubuntu Trusty (failure harder to reproduce on Fedora or MacOS)

For Ubuntu guaranteed way to reproduce is a command like this:

for i in {1..10}; do tox -epy27 'oslo_messaging.tests.drivers.zmq.test_zmq_ack_manager.TestZmqAckManager'; done

about 3 times out of 10 is a failure.

The trace for the failure is:

FAIL: oslo_messaging.tests.drivers.zmq.test_zmq_ack_manager.TestZmqAckManager.test_cast_failure_exhausted_retries
tags: worker-1
----------------------------------------------------------------------
Empty attachments:
  stdout

stderr: {{{
WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] No ack received within 5 seconds for 800f4210-6c51-11e6-b38d-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] No ack received within 5 seconds for 800f4210-6c51-11e6-b38d-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.server.consumers.zmq_dealer_consumer] [ozamiatin-pc/topic.server/fef18ec4-7978-457d-a23b-28604aefc92b] Dropping duplicate CAST message 800f4210-6c51-11e6-b38d-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] No ack received within 5 seconds for 800f4210-6c51-11e6-b38d-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] Exhausted number of retries for 800f4210-6c51-11e6-b38d-40167e709c0f
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
   ERROR [oslo_messaging._drivers.zmq_driver.proxy.zmq_queue_proxy] Received message with wrong format
}}}

Traceback (most recent call last):
  File "/home/admin/zmq-acks/oslo.messaging/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
    return func(*args, **keywargs)
  File "oslo_messaging/tests/drivers/zmq/test_zmq_ack_manager.py", line 183, in test_cast_failure_exhausted_retries
    self.assertEqual(3, lost_ack_mock.call_count)
  File "/home/admin/zmq-acks/oslo.messaging/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual
    self.assertThat(observed, matcher, message)
  File "/home/admin/zmq-acks/oslo.messaging/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat
    raise mismatch_error
testtools.matchers._impl.MismatchError: 3 != 2
Ran 6 tests in 20.023s (+0.005s)
FAILED (id=15, failures=1 (+1))
error: testr failed (1)

[Oleksii Zamiatin (ozamiatin)]

FAIL: oslo_messaging.tests.drivers.zmq.test_zmq_ack_manager.TestZmqAckManager.test_cast_failure_exhausted_retries
tags: worker-1
----------------------------------------------------------------------
Empty attachments:
  stdout

stderr: {{{
WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] No ack received within 5 seconds for a417aaae-6c5f-11e6-b2fe-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] No ack received within 5 seconds for a417aaae-6c5f-11e6-b2fe-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.server.consumers.zmq_dealer_consumer] [ozamiatin-pc/topic.server/7dc38f34-92c1-485f-b2fe-25452a121918] Dropping duplicate CAST message a417aaae-6c5f-11e6-b2fe-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] No ack received within 5 seconds for a417aaae-6c5f-11e6-b2fe-40167e709c0f
 WARNING [oslo_messaging._drivers.zmq_driver.client.zmq_ack_manager] Exhausted number of retries for a417aaae-6c5f-11e6-b2fe-40167e709c0f
}}}

Traceback (most recent call last):
  File "/home/admin/zmq-acks/oslo.messaging/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
    return func(*args, **keywargs)
  File "oslo_messaging/tests/drivers/zmq/test_zmq_ack_manager.py", line 183, in test_cast_failure_exhausted_retries
    self.assertEqual(3, lost_ack_mock.call_count)
  File "/home/admin/zmq-acks/oslo.messaging/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual
    self.assertThat(observed, matcher, message)
  File "/home/admin/zmq-acks/oslo.messaging/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat
    raise mismatch_error
testtools.matchers._impl.MismatchError: 3 != 2
Ran 6 tests in 20.016s (+0.001s)
FAILED (id=9, failures=1 (+1))
error: testr failed (1)

[Gevorg Davoian (gdavoian)]

I have noticed so far that single tests from TestZmqAckManager never fail (even being launched 10-100 times in a row). They starts failing when being launched together. I will continue investigating.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/366179

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/366179
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=09816f0451cb0eccefbd70c3a40cac18c4456e1a
Submitter: Jenkins
Branch: master

commit 09816f0451cb0eccefbd70c3a40cac18c4456e1a
Author: Gevorg Davoian <email address hidden>
Date: Tue Sep 6 17:53:05 2016 +0300

    [zmq] Fix TestZmqAckManager periodic failure

    Change-Id: I011b80ae2db094cd34615b80e71a6545833d8ace
    Closes-Bug: #1617560

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.messaging 5.11.0 release.