Notification processing failure causes notifications to get stuck

[Mark Goddard]

While testing compute node failover, I hit the following issue. Steps to reproduce:

* disable fencing
* create a VM
* kill pacemaker-remote on the compute node running the VM, leave nova-compute running

A notification is generated, and masakari disables the compute service. However, when it tries to evacuate the instance, it fails because nova-compute is still running. I suppose this is expected, since we haven't fenced the node. However, we see the following issue:

2020-07-31 09:03:39.688 6 INFO masakari.engine.manager [req-11dbb1bf-35c5-4865-a565-88e701b0771e bdc8ea78517649048f945b4c93d0fd12 523ce2afdf824732b04d7ba419bc0508 - - -] Processing notification 20b2d9f6-3
446-4571-90e0-6d0441fd1e5e of type: COMPUTE_HOST
2020-07-31 09:03:40.233 6 INFO masakari.compute.nova [req-9deac789-7364-4c38-915d-8ebd7efaece2 nova - - - -] Disable nova-compute on rested-man.maas
2020-07-31 09:03:40.441 6 INFO masakari.engine.drivers.taskflow.host_failure [req-9deac789-7364-4c38-915d-8ebd7efaece2 nova - - - -] Sleeping 180 sec before starting recovery thread until nova recognizes
the node down.
2020-07-31 09:06:40.460 6 INFO masakari.compute.nova [req-333cd067-12b7-4fa1-880c-5e4cf9f03d55 nova - - - -] Fetch Server list on rested-man.maas
2020-07-31 09:06:41.221 6 INFO masakari.compute.nova [req-ad6b4326-401a-44f4-8c91-926e780d6864 nova - - - -] Call get server command for instance 671f4a8d-af0d-4797-bdb3-d95ee0269898
2020-07-31 09:06:41.819 6 INFO masakari.compute.nova [req-18caaf81-554e-47ab-8adb-d1fe1ee1be56 nova - - - -] Call get server command for instance 671f4a8d-af0d-4797-bdb3-d95ee0269898
2020-07-31 09:06:42.415 6 INFO masakari.compute.nova [req-1b9fae9a-0983-4b98-a9f2-9399db65b1e2 nova - - - -] Call lock server command for instance 671f4a8d-af0d-4797-bdb3-d95ee0269898
2020-07-31 09:06:43.047 6 INFO masakari.compute.nova [req-1b9fae9a-0983-4b98-a9f2-9399db65b1e2 nova - - - -] Call evacuate command for instance 671f4a8d-af0d-4797-bdb3-d95ee0269898 on host None
2020-07-31 09:06:43.639 6 INFO masakari.compute.nova [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Call unlock server command for instance 671f4a8d-af0d-4797-bdb3-d95ee0269898
2020-07-31 09:06:44.341 6 WARNING masakari.engine.drivers.taskflow.driver [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Task 'EvacuateInstancesTask' (3e129d65-cce2-468f-869a-9372984ceee5) transi
tioned into state 'FAILURE' from state 'RUNNING'
4 predecessors (most recent first):
  Flow 'post_tasks'
  |__Flow 'main_tasks'
     |__Flow 'pre_tasks'
        |__Flow 'instance_evacuate_engine': masakari.exception.HostRecoveryFailureException: Failed to evacuate instances '671f4a8d-af0d-4797-bdb3-d95ee0269898' from host 'rested-man.maas'
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver Traceback (most recent call last):
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver File "/var/lib/kolla/venv/lib/python3.6/site-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver result = task.execute(**arguments)
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/drivers/taskflow/host_failure.py", line 387, in execute
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver _do_evacuate(self.context, host_name, instance_list)
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/drivers/taskflow/host_failure.py", line 368, in _do_evacuate
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver message=msg)
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver masakari.exception.HostRecoveryFailureException: Failed to evacuate instances '671f4a8d-af0d-4797-bdb3-d95ee0269898' from host 'rested-man.maas'
2020-07-31 09:06:44.341 6 ERROR masakari.engine.drivers.taskflow.driver
2020-07-31 09:06:44.345 6 WARNING masakari.engine.drivers.taskflow.driver [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Task 'EvacuateInstancesTask' (3e129d65-cce2-468f-869a-9372984ceee5) transitioned into state 'REVERTED' from state 'REVERTING'
2020-07-31 09:06:44.347 6 WARNING masakari.engine.drivers.taskflow.driver [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Task 'PrepareHAEnabledInstancesTask' (e35a80ed-38ea-4866-8549-0b07c5f07db4) transitioned into state 'REVERTED' from state 'REVERTING'
2020-07-31 09:06:44.359 6 WARNING masakari.engine.drivers.taskflow.driver [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Task 'DisableComputeServiceTask' (9ef14618-9a0d-4281-b6eb-d6f83dfb5ea9) transitioned into state 'REVERTED' from state 'REVERTING'
2020-07-31 09:06:44.361 6 WARNING masakari.engine.drivers.taskflow.driver [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Flow 'instance_evacuate_engine' (72f2b5a2-fcd3-4c01-b426-d5fa00f2fc01) transitioned into state 'REVERTED' from state 'RUNNING'
2020-07-31 09:06:44.361 6 ERROR masakari.engine.manager [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Failed to process notification '20b2d9f6-3446-4571-90e0-6d0441fd1e5e'. Reason: Failed to evacuate instances '671f4a8d-af0d-4797-bdb3-d95ee0269898' from host 'rested-man.maas': masakari.exception.HostRecoveryFailureException: Failed to evacuate instances '671f4a8d-af0d-4797-bdb3-d95ee0269898' from host 'rested-man.maas'
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server [req-0ff038ca-d59a-4be9-aef9-6d04247f9e76 nova - - - -] Exception during message handling: IndexError: list index out of range
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 274, in dispatch
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/manager.py", line 321, in process_notification
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server self._process_notification(context, notification)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/manager.py", line 317, in _process_notification
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server do_process_notification(notification)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/utils.py", line 267, in inner
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server return f(*args, **kwargs)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/manager.py", line 299, in do_process_notification
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server context, notification)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/manager.py", line 248, in _handle_notification_type_host
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server tb=tb)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/utils.py", line 47, in notify_about_notification_update
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server fault, priority = _get_fault_and_priority_from_exc_and_tb(exception, tb)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/engine/utils.py", line 31, in _get_fault_and_priority_from_exc_and_tb
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server exception, tb)
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/lib/python3.6/site-packages/masakari/notifications/objects/exception.py", line 39, in from_exc_and_traceback
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server trace = inspect.trace()[-1]
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server IndexError: list index out of range
2020-07-31 09:06:44.361 6 ERROR oslo_messaging.rpc.server

Masakari calls inspect.trace outside of an except clause, which returns an empty list. It then tries to get the last item of the list, which results in an IndexError.

This leaves the notification in a running state, since masakari does not clean it up.

+--------------------------------------+----------------------------+---------+--------------+--------------------------------------+----------------------------------------------------------------------------+
| notification_uuid | generated_time | status | type | source_host_uuid | payload |
+--------------------------------------+----------------------------+---------+--------------+--------------------------------------+----------------------------------------------------------------------------+
| 20b2d9f6-3446-4571-90e0-6d0441fd1e5e | 2020-07-31T09:02:27.000000 | running | COMPUTE_HOST | 0f706778-6765-408a-86d8-08ad1e7367a6 | {'event': 'STOPPED', 'cluster_status': 'OFFLINE', 'host_status': 'NORMAL'} |
+--------------------------------------+----------------------------+---------+--------------+--------------------------------------+----------------------------------------------------------------------------+

This prevents the segment host from being updated. I had to manually delete the notification from the DB.

use masakari
delete from notifications where notification_uuid='20b2d9f6-3446-4571-90e0-6d0441fd1e5e';

There are probably two issues here.

1. don't assume we are in an except clause
2. move the notification to error state if processing fails

[OpenStack Infra (hudson-openstack)]

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

[Radosław Piliszek (yoctozepto)]

bug confirmed

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/744138
Committed: https://git.openstack.org/cgit/openstack/masakari/commit/?id=69a9a41802edf21c8e4784835654697e13db9ca2
Submitter: Zuul
Branch: master

commit 69a9a41802edf21c8e4784835654697e13db9ca2
Author: Mark Goddard <email address hidden>
Date: Fri Jul 31 12:26:16 2020 +0100

    Fix exception notification with no trace

    The Exception notification code calls inspect.trace(), which returns an
    empty list if called outside of an except clause. The returned list is
    then indexed, causing an IndexError. In fact, every use of this
    exception in the engine is from outside of an except clause.

    This can affect notification processing, causing notifications to get
    stuck in a running state, requiring manual DB deletion.

    This change addresses the issue by checking whether the list returned by
    inspect.trace() is empty.

    A more complete solution would involve checking every call path to the
    exception notification, and ensuring that it is made from an except
    clause.

    Change-Id: I01af664d53db20041ac7306d2bca63254ffc9ede
    Partial-Bug: #1889765

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/ussuri
Review: https://review.opendev.org/744914

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/train
Review: https://review.opendev.org/744915

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/stein
Review: https://review.opendev.org/744916

[mikhail (kraynovmv)]

Hello @mgoddard, do you have ETA when the fix will be released to stable/train?

[Mark Goddard (mgoddard)]

@mikhail, it is not in my control. Please show your enthusiasm on these reviews: https://review.opendev.org/#/q/I01af664d53db20041ac7306d2bca63254ffc9ede

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/744916
Committed: https://git.openstack.org/cgit/openstack/masakari/commit/?id=fc3cdd7520aea14d5d380a485d3fd72f283c13e7
Submitter: Zuul
Branch: stable/stein

commit fc3cdd7520aea14d5d380a485d3fd72f283c13e7
Author: Mark Goddard <email address hidden>
Date: Fri Jul 31 12:26:16 2020 +0100

    Fix exception notification with no trace

    The Exception notification code calls inspect.trace(), which returns an
    empty list if called outside of an except clause. The returned list is
    then indexed, causing an IndexError. In fact, every use of this
    exception in the engine is from outside of an except clause.

    This can affect notification processing, causing notifications to get
    stuck in a running state, requiring manual DB deletion.

    This change addresses the issue by checking whether the list returned by
    inspect.trace() is empty.

    A more complete solution would involve checking every call path to the
    exception notification, and ensuring that it is made from an except
    clause.

    Change-Id: I01af664d53db20041ac7306d2bca63254ffc9ede
    Partial-Bug: #1889765
    (cherry picked from commit 69a9a41802edf21c8e4784835654697e13db9ca2)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/744915
Committed: https://git.openstack.org/cgit/openstack/masakari/commit/?id=087f2658915fdbe46b5124d681ae18000fb90015
Submitter: Zuul
Branch: stable/train

commit 087f2658915fdbe46b5124d681ae18000fb90015
Author: Mark Goddard <email address hidden>
Date: Fri Jul 31 12:26:16 2020 +0100

    Fix exception notification with no trace

    The Exception notification code calls inspect.trace(), which returns an
    empty list if called outside of an except clause. The returned list is
    then indexed, causing an IndexError. In fact, every use of this
    exception in the engine is from outside of an except clause.

    This can affect notification processing, causing notifications to get
    stuck in a running state, requiring manual DB deletion.

    This change addresses the issue by checking whether the list returned by
    inspect.trace() is empty.

    A more complete solution would involve checking every call path to the
    exception notification, and ensuring that it is made from an except
    clause.

    Change-Id: I01af664d53db20041ac7306d2bca63254ffc9ede
    Partial-Bug: #1889765
    (cherry picked from commit 69a9a41802edf21c8e4784835654697e13db9ca2)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/744914
Committed: https://git.openstack.org/cgit/openstack/masakari/commit/?id=f0434014568bab29d5642dee4817267b6b2ff4e7
Submitter: Zuul
Branch: stable/ussuri

commit f0434014568bab29d5642dee4817267b6b2ff4e7
Author: Mark Goddard <email address hidden>
Date: Fri Jul 31 12:26:16 2020 +0100

    Fix exception notification with no trace

    The Exception notification code calls inspect.trace(), which returns an
    empty list if called outside of an except clause. The returned list is
    then indexed, causing an IndexError. In fact, every use of this
    exception in the engine is from outside of an except clause.

    This can affect notification processing, causing notifications to get
    stuck in a running state, requiring manual DB deletion.

    This change addresses the issue by checking whether the list returned by
    inspect.trace() is empty.

    A more complete solution would involve checking every call path to the
    exception notification, and ensuring that it is made from an except
    clause.

    Change-Id: I01af664d53db20041ac7306d2bca63254ffc9ede
    Partial-Bug: #1889765
    (cherry picked from commit 69a9a41802edf21c8e4784835654697e13db9ca2)

[Pedro Guimarães (pguimaraes)]

I can reproduce this issue on the following scenario:

1) Create a segment and add the node
2) Create enough VMs so Masakari will take some time on the evacuation (e.g. 30 VMs)
3) Reboot the node
4) Masakari starts the migration of the VMs
5) Node eventually comes back and nova-compute is up & running while Masakari is still evacuating VMs

[James Page (james-page)]

>Ubuntu SRU information<

[Impact]
During a server hard failure (power off) Masakari will fail to complete recovery of impacted instances if the server comes back up before Masakari has completed recovery of all instances.

[Test Case]
Deploy OpenStack with Masakari configuration (using the OpenStack Charms)
1) Create a segment and add the node
2) Create enough VMs so Masakari will take some time on the evacuation (e.g. 30 VMs)
3) Reboot the node
4) Masakari starts the migration of the VMs
5) Node eventually comes back and nova-compute is up & running while Masakari is still evacuating VMs

[Regression Potential]
The proposed cherry pick resolves some incorrect assumptions in the exception processing within Masakari which resolves this issue; behaviour is not changed and the fix has been upstream in Masakari for some time.

[Łukasz Zemczak (sil2100)]

Hello Mark, or anyone else affected,

Accepted masakari into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/masakari/9.0.0-0ubuntu0.20.04.5 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[James Page (james-page)]

Hello Mark, or anyone else affected,

Accepted masakari into ussuri-proposed. The package will build now and be available in the Ubuntu Cloud Archive in a few hours, and then in the -proposed repository.

Please help us by testing this new package. To enable the -proposed repository:

  sudo add-apt-repository cloud-archive:ussuri-proposed
  sudo apt-get update

Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-ussuri-needed to verification-ussuri-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-ussuri-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Pedro Guimarães (pguimaraes)]

Hi @james-page, I've ran the package in focal-proposed:

 *** 9.0.0-0ubuntu0.20.04.5 500
        500 http://archive.ubuntu.com/ubuntu focal-proposed/main amd64 Packages

And I can see that now notifications do not get stuck in "running" anymore, but move to "failed" when an error happens. That fixed the bug for me.

[James Page (james-page)]

Amended tags inline with what @pguimaraes actually tested which was the packages in focal-proposed (not in the UCA for Ussuri on Bionic).

[Corey Bryant (corey.bryant)]

The verification of the Stable Release Update for masakari has completed successfully and the package has now been released to -updates. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Corey Bryant (corey.bryant)]

This bug was fixed in the package masakari - 9.0.0-0ubuntu0.20.04.5~cloud0
---------------

 masakari (9.0.0-0ubuntu0.20.04.5~cloud0) bionic-ussuri; urgency=medium
 .
   * New update for the Ubuntu Cloud Archive.
 .
 masakari (9.0.0-0ubuntu0.20.04.5) focal; urgency=medium
 .
   * d/p/bug1889765.patch: Cherry pick fix to resolve issues with
     processing of notifications when hypervisors get bounced
     (LP: #1889765).

[Corey Bryant (corey.bryant)]

Apologies, I promoted this one along with https://bugs.launchpad.net/cloud-archive/ussuri/+bug/1782517. I've reached out to Pedro to see if he happens to have testing underway.

[Pedro Guimarães (pguimaraes)]

Hi, downgraded masakari units to Bionic and re-ran the same test scenario. I can also see notifications eventually fail and do not get stuck in "running". Adding tag for bionic as well.

[Launchpad Janitor (janitor)]

This bug was fixed in the package masakari - 9.0.0-0ubuntu0.20.04.5

---------------
masakari (9.0.0-0ubuntu0.20.04.5) focal; urgency=medium

  * d/p/bug1889765.patch: Cherry pick fix to resolve issues with
    processing of notifications when hypervisors get bounced
    (LP: #1889765).

 -- James Page <email address hidden> Fri, 11 Jun 2021 14:55:59 +0100