gate failure : testtools.matchers._impl.MismatchError: 'volume.retype' != 'backup.createprogress'

[Rajat Dhasmana]

Recently a lot of gate failures are occurring with the following trace :

ft1.24: cinder.tests.unit.volume.test_volume_migration.VolumeMigrationTestCase.test_retype_volume_driver_success_StringException: pythonlogging:'': {{{
2018-11-09 08:31:01,386 INFO [keystonemiddleware.auth_token] Starting Keystone auth_token middleware
2018-11-09 08:31:01,392 WARNING [keystonemiddleware._common.config] The option "auth_url" in conf is not known to auth_token
2018-11-09 08:31:01,392 WARNING [keystonemiddleware.auth_token] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.
2018-11-09 08:31:01,395 WARNING [keystonemiddleware.auth_token] Configuring www_authenticate_uri to point to the public identity endpoint is required; clients may not be able to authenticate against an admin endpoint
2018-11-09 08:31:01,414 INFO [cinder.rpc] Automatically selected cinder-scheduler objects version 1.37 as minimum service version.
2018-11-09 08:31:01,416 INFO [cinder.rpc] Automatically selected cinder-scheduler RPC version 3.11 as minimum service version.
2018-11-09 08:31:01,454 INFO [cinder.volume.manager] Determined volume DB was empty at startup.
2018-11-09 08:31:01,458 INFO [cinder.volume.manager] Service not found for updating active_backend_id, assuming default for driver init.
2018-11-09 08:31:01,460 INFO [cinder.volume.manager] Image-volume cache disabled for host ubuntu-xenial-rax-ord-0000445459.
2018-11-09 08:31:01,464 INFO [cinder.rpc] Automatically selected cinder-volume objects version 1.37 as minimum service version.
2018-11-09 08:31:01,466 INFO [cinder.rpc] Automatically selected cinder-volume RPC version 3.16 as minimum service version.
2018-11-09 08:31:01,583 WARNING [cinder.quota] Deprecated: Default quota for resource: volumes_new is set by the default quota flag: quota_volumes_new, it is now deprecated. Please use the default quota class for default quota.
2018-11-09 08:31:01,583 WARNING [cinder.quota] Deprecated: Default quota for resource: gigabytes_new is set by the default quota flag: quota_gigabytes_new, it is now deprecated. Please use the default quota class for default quota.
2018-11-09 08:31:01,625 WARNING [cinder.quota] Deprecated: Default quota for resource: gigabytes_old is set by the default quota flag: quota_gigabytes_old, it is now deprecated. Please use the default quota class for default quota.
2018-11-09 08:31:01,625 WARNING [cinder.quota] Deprecated: Default quota for resource: volumes_old is set by the default quota flag: quota_volumes_old, it is now deprecated. Please use the default quota class for default quota.
2018-11-09 08:31:01,655 INFO [cinder.volume.manager] Volume f4823709-9d3e-44da-84c2-01e94879ccf4: retyped successfully.
2018-11-09 08:31:01,703 WARNING [cinder.volume.manager] Attempt to update service_uuid resulted in a Service NotFound exception, service_uuid field on volumes will be NULL.
2018-11-09 08:31:01,705 INFO [cinder.volume.manager] Retype volume completed successfully.
}}}

Traceback (most recent call last):
  File "/home/zuul/src/git.openstack.org/openstack/cinder/cinder/tests/unit/volume/test_volume_migration.py", line 910, in test_retype_volume_driver_success
    self._retype_volume_exec(True)
  File "/home/zuul/src/git.openstack.org/openstack/cinder/.tox/lower-constraints/lib/python3.5/site-packages/mock/mock.py", line 1305, in patched
    return func(*args, **keywargs)
  File "/home/zuul/src/git.openstack.org/openstack/cinder/cinder/tests/unit/volume/test_volume_migration.py", line 891, in _retype_volume_exec
    (['INFO', 'volume.retype'],))
  File "/home/zuul/src/git.openstack.org/openstack/cinder/cinder/test.py", line 401, in assert_notify_called
    self.assertEqual(call[1], posargs[2])
  File "/home/zuul/src/git.openstack.org/openstack/cinder/.tox/lower-constraints/lib/python3.5/site-packages/testtools/testcase.py", line 411, in assertEqual
    self.assertThat(observed, matcher, message)
  File "/home/zuul/src/git.openstack.org/openstack/cinder/.tox/lower-constraints/lib/python3.5/site-packages/testtools/testcase.py", line 498, in assertThat
    raise mismatch_error
testtools.matchers._impl.MismatchError: 'volume.retype' != 'backup.createprogress'

This seems to be a race problem between the rpc notifier of retype and backup.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[Yikun Jiang (yikunkero)]

diff --git a/cinder/tests/unit/fake_notifier.py b/cinder/tests/unit/fake_notifier.py
index 7e07a26..8a5fef0 100644
--- a/cinder/tests/unit/fake_notifier.py
+++ b/cinder/tests/unit/fake_notifier.py
@@ -49,6 +49,8 @@ class FakeNotifier(object):
         return len(self.notifications)

     def _notify(self, priority, ctxt, event_type, payload):
+ if event_type=='backup.createprogress':
+ import pdb;pdb.set_trace()
         payload = self._serializer.serialize_entity(ctxt, payload)
         # NOTE(sileht): simulate the kombu serializer
         # this permit to raise an exception if something have not

tox -e py27 > res

# cat res |grep ^cinder.tests | sort
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_backup_metadata_fail
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_backup_metadata_fail2
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_bz2
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_cmp_shafiles
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_custom_container
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_default_container
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_delta_two_blocks_in_object_change
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_delta_two_objects_change
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_shafile
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_uncompressed
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_backup_zlib
cinder.tests.unit.backup.drivers.test_backup_google.GoogleBackupDriverTestCase.test_restore_delta
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_backup_metadata_fail
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_backup_metadata_fail2
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_bz2
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_cmp_shafiles
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_custom_container
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_default_container
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_delta_two_blocks_in_object_change
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_delta_two_objects_change
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_shafile
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_backup_uncompressed
cinder.tests.unit.backup.drivers.test_backup_nfs.BackupNFSSwiftBasedTestCase.test_b...

[OpenStack Infra (hudson-openstack)]

Change abandoned by Rajat Dhasmana (<email address hidden>) on branch: master
Review: https://review.openstack.org/618457

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/618670
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=a2b9d4dd9bff6dab5047cd5841672c8cb22d9d37
Submitter: Zuul
Branch: master

commit a2b9d4dd9bff6dab5047cd5841672c8cb22d9d37
Author: whoami-rajat <email address hidden>
Date: Mon Nov 19 09:24:01 2018 +0530

    Tests : notifier problem with backup

    There appears to be a race condition while sending notifications
    to ceilometer with rpc.
    the backup.createprogress notification seems to be leaking which
    appears to be the main cause of the failures.
    This patch addresses the issue.

    Change-Id: I460a270eba61cdca131717f7dfe726841a509378
    Closes-Bug: #1803648

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/618499
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=593d8dfa79980db651b88957f766604240e64e76
Submitter: Zuul
Branch: master

commit 593d8dfa79980db651b88957f766604240e64e76
Author: Yikun Jiang <email address hidden>
Date: Fri Nov 16 17:42:41 2018 +0800

    An alternate way to fix retype notifier test case

    When we do backup for a volume, the backup notification is called
    periodically, but if we do other operations (like retype operation)
    in parallel, there is a possible to record the "volume.retype" and
    "backup.createprogress".

    This patch try to mock the send notification methods to ensure this
    doesn't happen.

    Cloeses-Bug: #1803648

    Co-Authored-By: Rajat Dhasmana <email address hidden>

    Change-Id: I4c44cdd6a4a11a3b7b5c57ff5aac19a8d01ef124

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/625644

[Rajat Dhasmana (whoami-rajat)]

The issue still persists

http://logs.openstack.org/47/626947/1/check/openstack-tox-py35/ea9b399/testr_results.html.gz

[Yikun Jiang (yikunkero)]

Oh god, After using the same method mentioned in #4, I found I forgot to also update this test setup:
https://review.openstack.org/#/c/618499/3/cinder/tests/unit/backup/drivers/test_backup_nfs.py@209

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/627329
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=32ef92fa4bc7b7db6df1c023b6460fb25474b0f5
Submitter: Zuul
Branch: master

commit 32ef92fa4bc7b7db6df1c023b6460fb25474b0f5
Author: Yikun Jiang <email address hidden>
Date: Wed Dec 26 10:58:13 2018 +0800

    Fix retype notifier test case (BackupNFSTestCase)

    When we do backup for a volume, the backup notification is called
    periodically, but if we do other operations (like retype operation)
    in parallel, there is a possible to record the "volume.retype" and
    "backup.createprogress".

    This patch try to mock the send notification methods to ensure this
    doesn't happen.

    Change-Id: Iad899944b54a0556ff0a946d18fcdb7e1680de69
    Closes-Bug: #1803648

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/625644
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=15c7ac73bc49a4d67c256890ff7ac259a4d001e2
Submitter: Zuul
Branch: stable/rocky

commit 15c7ac73bc49a4d67c256890ff7ac259a4d001e2
Author: Yikun Jiang <email address hidden>
Date: Fri Nov 16 17:42:41 2018 +0800

    An alternate way to fix retype notifier test case

    When we do backup for a volume, the backup notification is called
    periodically, but if we do other operations (like retype operation)
    in parallel, there is a possible to record the "volume.retype" and
    "backup.createprogress".

    This patch try to mock the send notification methods to ensure this
    doesn't happen.

    Cloeses-Bug: #1803648

    Co-Authored-By: Rajat Dhasmana <email address hidden>

    Change-Id: I4c44cdd6a4a11a3b7b5c57ff5aac19a8d01ef124
    (cherry picked from commit 593d8dfa79980db651b88957f766604240e64e76)

[Yikun Jiang (yikunkero)]

@mriedem add this bug to elastic-recheck in [1], and it shows that this bug is still triggered.

from 9.Jan, 3 fails in 24 hrs / 32 fails in 10 days

[1] https://review.openstack.org/#/c/631663/

[Yikun Jiang (yikunkero)]

Some investigation:
1. The cinder base test case using FakeNotifier mocks out all the real notifier [1][2].
2. [3][4] mock all the backup.createprogress related test case.
3. #4 shows the way to find all backup.createprogress info, after [3][4], all backup.createprogress notify has been mocked.

[1] https://github.com/openstack/cinder/blob/785435a/cinder/test.py#L271
[2] https://github.com/openstack/cinder/blob/master/cinder/tests/unit/fake_notifier.py#L68
[3] https://review.openstack.org/618499
[4] https://review.openstack.org/625644

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/638510
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=6f9135b6a48d7e900e8b33adf1e69c2463eac852
Submitter: Zuul
Branch: master

commit 6f9135b6a48d7e900e8b33adf1e69c2463eac852
Author: Eric Harney <email address hidden>
Date: Thu Feb 21 15:05:14 2019 -0500

    Tests: Fix up migrate notify tests

    Search for notify calls in a way that ignores extra
    notifications.

    Remove mock_notify.assert_not_called()

    Partial-Bug: #1803648

    Change-Id: I5e0823453cbadbd7ab1dcaa3e651769629eb409e

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 14.0.0.0rc1 release candidate.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/649634

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/651328
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=d4c8a792da0fec2ba3547c101f396eb67cadc490
Submitter: Zuul
Branch: master

commit d4c8a792da0fec2ba3547c101f396eb67cadc490
Author: Eric Harney <email address hidden>
Date: Tue Apr 9 12:51:24 2019 -0400

    Tests: Fix up test_volume notify tests

    Search for notify calls in a way that ignores
    extra notifications.

    Partial-Bug: #1803648

    Change-Id: Id9c7991669ee0997c754da61d1f60d3a656606de

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/651513

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/649634
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=96c3892bb103b7318ed650da089c7da412e61116
Submitter: Zuul
Branch: stable/rocky

commit 96c3892bb103b7318ed650da089c7da412e61116
Author: Eric Harney <email address hidden>
Date: Thu Feb 21 15:05:14 2019 -0500

    Tests: Fix up migrate notify tests

    Search for notify calls in a way that ignores extra
    notifications.

    Remove mock_notify.assert_not_called()

    Partial-Bug: #1803648

    Change-Id: I5e0823453cbadbd7ab1dcaa3e651769629eb409e
    (cherry picked from commit 6f9135b6a48d7e900e8b33adf1e69c2463eac852)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/651513
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=8bf4a1e801950dc26c07d43ae56b81146595c7cd
Submitter: Zuul
Branch: stable/rocky

commit 8bf4a1e801950dc26c07d43ae56b81146595c7cd
Author: Eric Harney <email address hidden>
Date: Tue Apr 9 12:51:24 2019 -0400

    Tests: Fix up test_volume notify tests

    Search for notify calls in a way that ignores
    extra notifications.

    Partial-Bug: #1803648

    Change-Id: Id9c7991669ee0997c754da61d1f60d3a656606de
    (cherry picked from commit d4c8a792da0fec2ba3547c101f396eb67cadc490)

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/681318
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=c586d0886ad4b239831a0b4a1827a8b4d054c120
Submitter: Zuul
Branch: master

commit c586d0886ad4b239831a0b4a1827a8b4d054c120
Author: Eric Harney <email address hidden>
Date: Tue Sep 10 13:43:42 2019 -0400

    Fix up test_snapshot notify tests

    Search for notify calls in a way that ignores
    extra notifications.

    Change-Id: I90cbfdaad582900f3047acffbfcdd3189335ffbf
    Partial-Bug: #1803648

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/681737
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=47f94ce24c5b3a21d1f004e466cd885b042b6894
Submitter: Zuul
Branch: stable/stein

commit 47f94ce24c5b3a21d1f004e466cd885b042b6894
Author: Eric Harney <email address hidden>
Date: Tue Sep 10 13:43:42 2019 -0400

    Fix up test_snapshot notify tests

    Search for notify calls in a way that ignores
    extra notifications.

    Change-Id: I90cbfdaad582900f3047acffbfcdd3189335ffbf
    Partial-Bug: #1803648
    (cherry picked from commit c586d0886ad4b239831a0b4a1827a8b4d054c120)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/queens
Review: https://review.opendev.org/686523

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/686523
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=ea39101a9c19f61cd5dec98986f67aad9518fdc4
Submitter: Zuul
Branch: stable/queens

commit ea39101a9c19f61cd5dec98986f67aad9518fdc4
Author: Eric Harney <email address hidden>
Date: Thu Feb 21 15:05:14 2019 -0500

    Tests: Fix up migrate notify tests

    Search for notify calls in a way that ignores extra
    notifications.

    Remove mock_notify.assert_not_called()

    Partial-Bug: #1803648

    Change-Id: I5e0823453cbadbd7ab1dcaa3e651769629eb409e
    (cherry picked from commit 6f9135b6a48d7e900e8b33adf1e69c2463eac852)
    (cherry picked from commit 96c3892bb103b7318ed650da089c7da412e61116)

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sean McGinnis (<email address hidden>) on branch: master
Review: https://review.opendev.org/632796
Reason: Been sitting for a while. Feel free to restore and update if still needed.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/cinder/+/785971
Committed: https://opendev.org/openstack/cinder/commit/ba8d19822b2212263934ec7ffe0bf2fb56b6c863
Submitter: "Zuul (22348)"
Branch: stable/ussuri

commit ba8d19822b2212263934ec7ffe0bf2fb56b6c863
Author: Eric Harney <email address hidden>
Date: Thu Mar 4 10:32:30 2021 -0500

    Tests: Don't assert notifier not called

    This doesn't work reliably -- it could be
    made to, but just skip this check for now
    to prevent spurious failures.

    Related-Bug: #1803648

    Change-Id: I8b67cc2d9a51f777a245739299e4bc44a7d0733b
    (cherry picked from commit 9f0be9994631fa2792f86dd27ffe539b8acbc686)

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/cinder/+/792408

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/cinder/+/792408
Committed: https://opendev.org/openstack/cinder/commit/8d84bdab6c012dcf67849eac6fc5fe232170d60d
Submitter: "Zuul (22348)"
Branch: master

commit 8d84bdab6c012dcf67849eac6fc5fe232170d60d
Author: Brian Rosmaita <email address hidden>
Date: Thu May 20 11:59:26 2021 -0400

    Tests: Don't assert notifier not called

    Same as change I8b67cc2d9a51, except for test_volume_migration.

    Change-Id: I6d16470934ec930fd9d431a06a37c35134ce7881
    Related-bug: #1803648