periodic notifier unit test failure

[gordon chung]

saw this in https://review.openstack.org/#/c/94483/,

seems like there's an edge case where notifier unit tests fails for no reason.

2014-05-21 02:47:20.990 | ======================================================================
2014-05-21 02:47:20.990 | FAIL: tests.alarm.test_rpc.TestRPCAlarmNotifier.test_notify_alarm
2014-05-21 02:47:20.990 | tags: worker-2
2014-05-21 02:47:20.990 | ----------------------------------------------------------------------
2014-05-21 02:47:20.990 | Traceback (most recent call last):
2014-05-21 02:47:20.990 | File "/home/jenkins/workspace/gate-ceilometer-python27/ceilometer/tests/alarm/test_rpc.py", line 107, in test_notify_alarm
2014-05-21 02:47:20.990 | self.notifier_server.notified[i]["alarm_id"])
2014-05-21 02:47:20.990 | File "/home/jenkins/workspace/gate-ceilometer-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 321, in assertEqual
2014-05-21 02:47:20.990 | self.assertThat(observed, matcher, message)
2014-05-21 02:47:20.990 | File "/home/jenkins/workspace/gate-ceilometer-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 406, in assertThat
2014-05-21 02:47:20.991 | raise mismatch_error
2014-05-21 02:47:20.991 | MismatchError: !=:
2014-05-21 02:47:20.991 | reference = '45aacb71-2499-4429-a001-b5e03a1f450a'
2014-05-21 02:47:20.991 | actual = 'bd51609f-9f57-45ef-b9fa-bae837bd691b'

[gordon chung (chungg)]

you can see issue in patchset 3 and patchset 7 of review

[gordon chung (chungg)]

another case:

2014-05-29 15:17:19.442 | ======================================================================
2014-05-29 15:17:19.442 | FAIL: tests.test_notification.TestRealNotification.test_notification_service
2014-05-29 15:17:19.442 | tags: worker-5
2014-05-29 15:17:19.442 | ----------------------------------------------------------------------
2014-05-29 15:17:19.442 | Empty attachments:
2014-05-29 15:17:19.442 | stderr
2014-05-29 15:17:19.443 | stdout
2014-05-29 15:17:19.443 |
2014-05-29 15:17:19.443 | Traceback (most recent call last):
2014-05-29 15:17:19.443 | File "/home/jenkins/workspace/gate-ceilometer-python26/.tox/py26/lib/python2.6/site-packages/mock.py", line 1201, in patched
2014-05-29 15:17:19.443 | return func(*args, **keywargs)
2014-05-29 15:17:19.444 | File "/home/jenkins/workspace/gate-ceilometer-python26/ceilometer/tests/test_notification.py", line 217, in test_notification_service
2014-05-29 15:17:19.444 | mock.call(mock.ANY, SamplesMatcher()),
2014-05-29 15:17:19.448 | File "/home/jenkins/workspace/gate-ceilometer-python26/.tox/py26/lib/python2.6/site-packages/mock.py", line 863, in assert_has_calls
2014-05-29 15:17:19.448 | 'Actual: %r' % (calls, self.mock_calls)
2014-05-29 15:17:19.448 | AssertionError: Calls not found.
2014-05-29 15:17:19.449 | Expected: [call(<ANY>, <tests.test_notification.SamplesMatcher object at 0x7692e50>), call(<ANY>, <tests.test_notification.SamplesMatcher object at 0x7692250>), call(<ANY>, <tests.test_notification.SamplesMatcher object at 0x76924d0>), call(<ANY>, <tests.test_notification.SamplesMatcher object at 0x7692110>), call(<ANY>, <tests.test_notification.SamplesMatcher object at 0x7692990>)]
2014-05-29 15:17:19.449 | Actual: [call(<ceilometer.openstack.common.context.RequestContext object at 0x7692bd0>, [<ceilometer.sample.Sample object at 0x7692850>])]

i'm raising importance since i see it happening more and more.

[Dina Belova (dbelova)]

Ok, Im starting looking on it)

[gordon chung (chungg)]

cool cool. no rush. just bumping it up because i see it more often. thanks for looking at it Dina.

[Dina Belova (dbelova)]

np - I'm just fighting with my testing lab, where tests do not work at all))) But I guess I'm close to the end of this mis-set-packages hell)

[Dina Belova (dbelova)]

I'm fighting to reproduce it, but I could not still... Probably there is some secret in the Jenkins job, dunno yet.

[Dina Belova (dbelova)]

I cannot reproduce the bug :( I see it in the Jenkins logs sometimes, but after ~20 tests runs I see no it (I used the known change as a base to reproduce it).

Will try it several more times, but the thing is that possibly we'll need to keep track on it and try to understand where it comes from, as now I see no way to catch it...

[gordon chung (chungg)]

i assume this is a timing issue... it's not a blocker since we can just recheck gate.

[Dina Belova (dbelova)]

Well, probably we can mark this as 'not a bug' with a comment like "not reproducible"? After 30+ tests reruns I see no this issue... Or I may try to run this on small VM - probably that might depend on the node performance. As my current testing lab is quite performant (8GB RAM | 4 VCPU | 80.0GB Disk). i may try to run this on some small VM - if that depends on this. @Gordon, what do you think?

[gordon chung (chungg)]

let's keep this open. it doesn't appear in local test but it is still visible in gate.

see: https://review.openstack.org/#/c/96706/

[Dina Belova (dbelova)]

okay, I'll try other testing env to catch it - possibly, we'll find it in this case.

[Dina Belova (dbelova)]

Issue keeps appearing in the gate: https://review.openstack.org/#/c/88506/45 and https://review.openstack.org/#/c/96653/5

[Dina Belova (dbelova)]

And here too : https://review.openstack.org/#/c/96752/
Quite strange situation, btw

[Dina Belova (dbelova)]

Yay, I found the way to reproduce it!
Finally start debugging :)

[Anita Kuno (anteaya)]

message:"FAIL: tests.test_notification.TestRealNotification.test_notification_service" OR message:"FAIL: tests.alarm.test_rpc.TestRPCAlarmNotifier.test_notify_alarm"

https://review.openstack.org/#/c/98149/3/queries/1321826.yaml

[Dina Belova (dbelova)]

well, not only here... On my test svn I got the following tests failed:

ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_alarm_history_constrained_by_timestamp (sqlite)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_alarm_history_constrained_by_timestamp (hbase)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_alarm_history_ordered_by_recentness (sqlite)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_alarm_history_ordered_by_recentness (hbase)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_recorded_alarm_history_preserved_after_deletion (sqlite)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_recorded_alarm_history_preserved_after_deletion (hbase)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_recorded_alarm_history_state_transition_on_behalf_of (sqlite)
ceilometer.tests.api.v2.test_alarm_scenarios.TestAlarms.test_get_recorded_alarm_history_state_transition_on_behalf_of (hbase)
ceilometer.tests.compute.pollsters.test_cpu.TestCPUPollster.test_get_samples

this bug is floating really

[Matt Riedemann (mriedem)]

Can we split test_notification_service into it's own bug report? They look like different failures, but I'm not sure if the root cause is the same somehow. But would be good to separate if not the same (or we don't know yet) so that we can uniquely fingerprint the fails in elastic-recheck.

[Matt Riedemann (mriedem)]

test_notification_service failure is now tracked in bug 1327344.

[Dina Belova (dbelova)]

As said, notification failure was fixed in the separated bug ^^^

As for the alarms failures, they are unittests runner specific, and not reproducing with testr and direct testtools usage, so that looks like unittests+mocking issue, not the ceilometer one.

[gordon chung (chungg)]

https://review.openstack.org/#/c/99891/
https://review.openstack.org/#/c/100453/