Notification related functional tests fails randomly due to KeyError

[Shilpa Devharakar]

Bug Description
===============
During whole functional test suite running, observed Notification related
functional tests fails randomly due to below KeyError

Masakari-engine Error logs:
===========================
2019-07-30 14:41:38.793 [[00;36mINFO masakari.compute.nova [[[01;36mreq-7842134b-75f0-4846-aa59-23c5bcadef60 [[00;36mservice None[[00;36m] [[01;35m[[00;36mCall get server command for instance 6d940329-123d-4608-80ff-d6ae2ca8b009[[00m[[00m
2019-07-30 14:41:39.238 [[00;32mDEBUG masakari.context [[[01;36mreq-34483244-d74e-4c87-a356-0386a527e7ee [[00;36mNone None[[00;32m] [[01;35m[[00;32mArguments dropped when creating context: {u'system_scope': None, u'project': u'93eac98cf37145e7a5d2ba17945e8ff9', 'client_timeout': None}[[00m [[00;33mfrom (pid=710) __init__ /opt/stack/masakari/masakari/context.py:113[[00m[[00m
2019-07-30 14:41:39.404 [[01;31mERROR masakari.engine.manager [[[01;36mreq-34483244-d74e-4c87-a356-0386a527e7ee [[00;36madmin admin[[01;31m] [[01;35m[[01;31mFailed to fetch notification recovery workflow details for ddd09acc-9793-42c7-9b7f-4139aa5f216c[[00m: KeyError: 'progress_details'
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00mTraceback (most recent call last):
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00m File "/opt/stack/masakari/masakari/engine/manager.py", line 371, in get_notification_recovery_workflow_details
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00m context, recovery_method, notification))
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00m File "/opt/stack/masakari/masakari/engine/drivers/taskflow/driver.py", line 328, in get_notification_recovery_workflow_details
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00m value.meta['progress_details']['details']
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00mKeyError: 'progress_details'
[[01;31m2019-07-30 14:41:39.404 TRACE masakari.engine.manager [[01;35m[[00m[[00m
2019-07-30 14:41:39.412 [[01;31mERROR oslo_messaging.rpc.server [[[01;36mreq-34483244-d74e-4c87-a356-0386a527e7ee [[00;36madmin admin[[01;31m] [[01;35m[[01;31mException during message handling[[00m: MasakariException: Failed to fetch notification recovery workflow details for ddd09acc-9793-42c7-9b7f-4139aa5f216c
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00mTraceback (most recent call last):
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m res = self.dispatcher.dispatch(message)
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 274, in dispatch
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m return self._do_dispatch(endpoint, method, ctxt, args)
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m result = func(ctxt, **new_args)
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m File "/opt/stack/masakari/masakari/engine/manager.py", line 377, in get_notification_recovery_workflow_details
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00m raise exception.MasakariException(msg)
[[01;31m2019-07-30 14:41:39.412 TRACE oslo_messaging.rpc.server [[01;35m[[00mMasakariException: Failed to fetch notification recovery workflow details for ddd09acc-9793-42c7-9b7f-4139aa5f216c

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/673526

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/673526
Committed: https://git.openstack.org/cgit/openstack/masakari/commit/?id=1b861d8b5694e4e211e26a25d4c88024731c804a
Submitter: Zuul
Branch: master

commit 1b861d8b5694e4e211e26a25d4c88024731c804a
Author: Shilpa Devharakar <email address hidden>
Date: Tue Jul 30 19:07:03 2019 +0530

    Notification functional tests fails randomly

    During notification functional tests, get_notification call fails
    randomly with KeyError during progress details retrieval, this patch
    fixes this issue.

    Change-Id: I89f47232eb6d106217717155441ba5bc1dfbaf98
    Closes-bug: #1838417

[Tony Karera (tonykarera)]

I think this is a bug
=====================
(masakari-engine)[masakari@controller1 masakari]$ cat masakari-engine.log
2021-04-13 04:21:14.382 7 INFO masakari.engine.driver [-] Loading masakari notification driver 'taskflow_driver'
2021-04-13 04:21:15.529 7 INFO masakari.service [-] Starting ha_engine (version 10.0.2)
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task [req-7a61257c-c0cf-488e-9db1-b5b357859267 - - - - -] Error during MasakariManager._process_unfinished_notifications: oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (1047, 'WSREP has not yet prepared node for application use')
[SQL: SELECT notifications.deleted_at AS notifications_deleted_at, notifications.deleted AS notifications_deleted, notifications.created_at AS notifications_created_at, notifications.updated_at AS notifications_updated_at, notifications.id AS notifications_id, notifications.notification_uuid AS notifications_notification_uuid, notifications.generated_time AS notifications_generated_time, notifications.type AS notifications_type, notifications.payload AS notifications_payload, notifications.status AS notifications_status, notifications.source_host_uuid AS notifications_source_host_uuid
FROM notifications
WHERE notifications.deleted = %(deleted_1)s AND notifications.status IN (%(status_1)s, %(status_2)s) ORDER BY notifications.created_at DESC, notifications.id DESC]
[parameters: {'deleted_1': 0, 'status_1': 'error', 'status_2': 'new'}]
(Background on this error at: http://sqlalche.me/e/13/e3q8)
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task Traceback (most recent call last):
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task File "/var/lib/kolla/venv/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task self.dialect.do_execute(
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task File "/var/lib/kolla/venv/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task cursor.execute(statement, parameters)
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task File "/var/lib/kolla/venv/lib/python3.8/site-packages/pymysql/cursors.py", line 163, in execute
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task result = self._query(query)
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task File "/var/lib/kolla/venv/lib/python3.8/site-packages/pymysql/cursors.py", line 321, in _query
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task conn.query(q)
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task File "/var/lib/kolla/venv/lib/python3.8/site-packages/pymysql/connections.py", line 505, in query
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task File "/var/lib/kolla/venv/lib/python3.8/site-packages/pymysql/connections.py", line 724, in _read_query_result
2021-04-13 04:43:29.921 7 ERROR oslo_service.periodic_task result.read()
2021-04-13 04:43:29.9...

[Radosław Piliszek (yoctozepto)]

Hello Tony, this bug is closed as fixed. Please open a new one if you experience another issue. Please describe what you have done etc.