The tempest test test_aodh.test_alarm_without_resource_id occasionally fails.
The reason:
-----------
- The test test_alarm_with_resource_id creates an Aodh alarm and then deletes it
- The next test, test_alarm_without_resource_id, creates an Aodh alarm and checks if there is a single Aodh alarm in the graph. Two alarms are found, since the alarm from the first test was not deleted yet.
Analysis:
---------
The problem is a delay of handling the alarm.deletion event that arrives from Aodh. Referring to these logs: http://logs.openstack.org/27/486927/6/gate/gate-vitrage-dsvm-datasources-py27-ubuntu-xenial/c190e4b/logs
tempest.txt.gz:
2017-07-27 05:40:36.262 10156 INFO vitrage_tempest_tests.tests.utils [-] Test End: test_alarm_with_resource_id
2017-07-27 05:40:36.264 10156 INFO vitrage_tempest_tests.tests.utils [-] Test Start: test_alarm_without_resource_id
2017-07-27 05:41:04.646 10156 ERROR vitrage_tempest_tests.tests.api.base [-] 1 != 2: Num vertices is incorrect for: aodh: MismatchError: 1 != 2: Num vertices is incorrect for: aodh
screen-vitrage-collector.txt.gz:
first alarm: ef0760e4-4510-4206-8408-c6dccc1f5f98
alarm.creation: Jul 27 05:39:37.228262
alarm.deletion: Jul 27 05:40:05.759333
Jul 27 05:41:49.542682 ubuntu-xenial-citycloud-la1-10110465 vitrage-collector[21677]: 2017-07-27 05:41:49.542 22826 DEBUG vitrage.datasources.alarm_driver_base [-] deleting cached_alarm {'description': u'test alarm', 'resource_id': u'09498c0b-7079-4be3-bd90-6640c187c700', 'vitrage_entity_type': 'aodh', 'timestamp': u'2017-07-27T05:39:37.125753', 'event_type': (u'*',), 'vitrage_datasource_action': 'snapshot', 'severity': u'low', 'vitrage_sample_date': '2017-07-27 05:39:49.412734+00:00', 'enabled': True, 'name': u'test_-85150', 'alarm_id': u'ef0760e4-4510-4206-8408-c6dccc1f5f98', 'state': u'alarm', 'repeat_actions': False, 'project_id': u'6c8e5ea27e0f42dcb594b40e3344ce79', 'type': u'event'} _filter_and_cache_alarms /opt/stack/new/vitrage/vitrage/datasources/alarm_driver_base.py:115
screen-vitrage-graph.txt.gz:
alarm.creation: Jul 27 05:39:37.228961
Jul 27 05:41:49.546773 : deleted
Jul 27 05:41:49.546773 ubuntu-xenial-citycloud-la1-10110465 vitrage-graph[21946]: {u'vitrage_datasource_action': u'snapshot', u'project_id': u'6c8e5ea27e0f42dcb594b40e3344ce79', u'type': u'event', u'description': u'test alarm', u'name': u'test_-85150', u'resource_id': u'09498c0b-7079-4be3-bd90-6640c187c700', u'vitrage_entity_type': u'aodh', u'timestamp': u'2017-07-27T05:39:37.125753', u'enabled': True, u'severity': u'low', u'vitrage_sample_date': u'2017-07-27 05:41:49.542561+00:00', u'state': u'alarm', u'repeat_actions': False, u'alarm_id': u'ef0760e4-4510-4206-8408-c6dccc1f5f98', u'vitrage_event_type': u'delete_entity', u'event_type': [u'*']} process_event /opt/stack/new/vitrage/vitrage/entity_graph/processor/processor.py:60
is_deleted=True: Jul 27 05:41:55.283126 ===> took a minute and a half since the first event
