Ceph » mgr » Dashboard

I tried to reproduce the issue on my local environment but unfortunately it didn't happen there.

2020-08-20T14:42:26.381 INFO:tasks.mgr.dashboard.helper:command result:
2020-08-20T14:42:26.382 INFO:tasks.cephfs_test_runner:
2020-08-20T14:42:26.382 INFO:tasks.cephfs_test_runner:======================================================================
2020-08-20T14:42:26.383 INFO:tasks.cephfs_test_runner:FAIL: test_pool_create (tasks.mgr.dashboard.test_pool.PoolTest)
2020-08-20T14:42:26.383 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2020-08-20T14:42:26.383 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2020-08-20T14:42:26.384 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-laura-testing-nautilus-batch-36607-36613-36692/qa/tasks/mgr/dashboard/test_pool.py", line 267, in test_pool_create
2020-08-20T14:42:26.384 INFO:tasks.cephfs_test_runner:    self.assertIn(conf, new_pool['configuration'])
2020-08-20T14:42:26.384 INFO:tasks.cephfs_test_runner:AssertionError: {'name': 'rbd_qos_bps_limit', 'source': 1, 'value': '2048'} not found in []
2020-08-20T14:42:26.385 INFO:tasks.cephfs_test_runner:
2020-08-20T14:42:26.385 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2020-08-20T14:42:26.385 INFO:tasks.cephfs_test_runner:Ran 123 tests in 4324.539s
2020-08-20T14:42:26.386 INFO:tasks.cephfs_test_runner:
2020-08-20T14:42:26.386 INFO:tasks.cephfs_test_runner:FAILED (failures=1)
2020-08-20T14:42:26.386 INFO:tasks.cephfs_test_runner:
2020-08-20T14:42:26.387 INFO:tasks.cephfs_test_runner:======================================================================
2020-08-20T14:42:26.388 INFO:tasks.cephfs_test_runner:FAIL: test_pool_create (tasks.mgr.dashboard.test_pool.PoolTest)
2020-08-20T14:42:26.388 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2020-08-20T14:42:26.388 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2020-08-20T14:42:26.388 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-laura-testing-nautilus-batch-36607-36613-36692/qa/tasks/mgr/dashboard/test_pool.py", line 267, in test_pool_create
2020-08-20T14:42:26.389 INFO:tasks.cephfs_test_runner:    self.assertIn(conf, new_pool['configuration'])
2020-08-20T14:42:26.389 INFO:tasks.cephfs_test_runner:AssertionError: {'name': 'rbd_qos_bps_limit', 'source': 1, 'value': '2048'} not found in []
2020-08-20T14:42:26.390 INFO:tasks.cephfs_test_runner:
2020-08-20T14:42:26.390 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/run_tasks.py", line 93, in run_tasks
    manager.__enter__()
  File "/usr/lib/python3.6/contextlib.py", line 81, in __enter__
    return next(self.gen)
  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-laura-testing-nautilus-batch-36607-36613-36692/qa/tasks/cephfs_test_runner.py", line 207, in task
    raise RuntimeError("Test failure: {0}".format(", ".join(bad_tests)))
RuntimeError: Test failure: test_pool_create (tasks.mgr.dashboard.test_pool.PoolTest)
2020-08-20T14:42:26.416 ERROR:teuthology.run_tasks: Sentry event: http://sentry.ceph.com/sepia/teuthology/?q=c72affb1f1d94dc593c31fc319416645
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/run_tasks.py", line 93, in run_tasks
    manager.__enter__()
  File "/usr/lib/python3.6/contextlib.py", line 81, in __enter__
    return next(self.gen)
  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-laura-testing-nautilus-batch-36607-36613-36692/qa/tasks/cephfs_test_runner.py", line 207, in task
    raise RuntimeError("Test failure: {0}".format(", ".join(bad_tests)))
RuntimeError: Test failure: test_pool_create (tasks.mgr.dashboard.test_pool.PoolTest)

- http://pulpito.ceph.com/laura-2020-08-20_12:55:29-rados:dashboard-wip-laura-testing-nautilus-batch-36607-36613-36692-distro-basic-smithi/
- http://pulpito.ceph.com/laura-2020-08-21_08:58:47-rados:dashboard-wip-laura-testing-nautilus-batch-36607-36613-36692-distro-basic-smithi/
- http://pulpito.ceph.com/laura-2020-08-25_07:37:15-rados:dashboard-wip-laura-testing-nautilus-batch-36607-36613-36692-distro-basic-smithi/

I ran the tests a few time now. It happens (not in every run) on my local environment as well.

rados/dashboard/{clusters/{2-node-mgr} debug/mgr objectstore/bluestore-hybrid

http://qa-proxy.ceph.com/teuthology/yuriw-2020-09-03_00:17:24-rados-wip-yuri-testing-2020-09-02-2252-nautilus-distro-basic-smithi/5400858/teuthology.log

/a/yuriw-2020-09-10_22:09:32-rados-wip-yuri2-testing-2020-09-10-0000-nautilus-distro-basic-smithi/5422088/teuthology.log
/a/yuriw-2020-09-10_22:09:32-rados-wip-yuri2-testing-2020-09-10-0000-nautilus-distro-basic-smithi/5422178/teuthology.log

https://jenkins.ceph.com/job/ceph-api/3115/

http://qa-proxy.ceph.com/teuthology/yuriw-2020-09-14_20:22:25-rados-wip-yuri8-testing-2020-09-14-1731-nautilus-distro-basic-smithi/5435559/teuthology.log

According to git blame qa/tasks/mgr/dashboard/test_pool.py in the nautilus branch, that test has not been modified for quite some time:

22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 250)             'configuration': {
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 251)                 'rbd_qos_bps_limit': 2048,
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 252)                 'rbd_qos_iops_limit': None,
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 253)             },
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 254)         }
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 255)         expected_configuration = [{
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 256)             'name': 'rbd_qos_bps_limit',
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 257)             'source': 1,
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 258)             'value': '2048',
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 259)         }, {
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 260)             'name': 'rbd_qos_iops_limit',
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 261)             'source': 0,
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 262)             'value': '0',
e6c1056ad5ad qa/tasks/mgr/dashboard/test_pool.py    (Sebastian Wagner 2018-03-21 17:15:29 +0100 263)         }]
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 264)         self._task_post('/api/pool/', pool)
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 265)         self.assertStatus(201)
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 266)         new_pool = self._get_pool(pool['pool'])
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 267)         self._validate_pool_properties(pool, new_pool)
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 268)         for conf in expected_configuration:
22dce7c3b51d qa/tasks/mgr/dashboard/test_pool.py    (Patrick Nawracay 2019-02-19 11:14:33 +0100 269)             self.assertIn(conf, new_pool['configuration'])
cbee3719580c qa/tasks/mgr/dashboard/test_pool.py    (Sebastian Wagner 2018-03-22 12:08:18 +0100 270) 

Did some recent backport into Nautilus make changes to the RBD QoS BPS settings? If I'm not mistaken, the test is expecting rbd_qos_bps_limit to be set to 2048, but the Ceph pool does not contain this value.

I've asked Mykola to take a look (as he's the original author of the RBD QoS feature), and he made the following observation:

I wonder couldn't it be related to https://github.com/ceph/ceph/pull/35367/

It has a change to src/pybind/mgr/dashboard/services/rbd.py, RbdConfiguration.list() function to return an empty configuration if the pool in a "bad" state. Can we check this somehow?

Another occurrence: https://pulpito.ceph.com/laura-2020-09-22_11:46:28-rados:dashboard-wip-laura-testing-nautilus-37278-distro-basic-smithi/

Stephan Müller wrote:

I tried to reproduce the failure with two different environments and in neither of them the failure could be reproduced.

Did you try to run all tests or just the pool suite?
Tatjana mentioned that she was able to reproduce it when running the pool suite, but it did not happen all the time.

Nautilus: https://jenkins.ceph.com/job/ceph-api/3750/

https://jenkins.ceph.com/view/mgr-dashboard/job/ceph-api-nightly-nautilus-backend/307/

This failure is reproducing in about 60-80% of "jenkins test api" runs in nautilus PRs at the moment.

Laura Paduano wrote:

Stephan Müller wrote:

I tried to reproduce the failure with two different environments and in neither of them the failure could be reproduced.

Did you try to run all tests or just the pool suite?
Tatjana mentioned that she was able to reproduce it when running the pool suite, but it did not happen all the time.

I ran the pool suite tests multiple times and used the API directly with different combinations via calling it directly using Insomnia (where I could replay the direct API calls) and through the dashboard.

As said it's not happening in my environments.

Just to confirm my assumption that the root cause is "len(pg_status) 1 and 'unknown' in pg_status[0]" condition check in RbdConfiguration.list function, I added some diagnostic there and created a test PR [1]. When it fails I see now [2]:

2020-10-01 04:19:26,758.758 INFO:__main__:Traceback (most recent call last):
2020-10-01 04:19:26,758.758 INFO:__main__:  File "/home/jenkins-build/build/workspace/ceph-api/qa/tasks/mgr/dashboard/test_pool.py", line 271, in test_pool_create
2020-10-01 04:19:26,758.758 INFO:__main__:    self.assertIn(conf, new_pool['configuration'])
2020-10-01 04:19:26,758.758 INFO:__main__:AssertionError: {'name': 'rbd_qos_bps_limit', 'source': 1, 'value': '2048'} not found in [{'source': 1, 'name': 'debug', 'value': 'pg_status is unknown'}]

The 'unknown' state means that pg peering is not complete yet, so it looks like the test just not wait long enough for pgs to peer after the pool is created.

Note, in the master we have a different condition here [3]: "len(pg_status) 1 and 'incomplete' in pg_status⁰". I.e. we check for all pg in 'incomplete' state. A pg enters incomplete state if the peering failed. So it is more correct check, still I don't like this too. It looks just like an attempt to make CI happy, not to fix a potential problem that may happen in reality. Usually you will not observe all pgs in incomplete state, but only some of them. And it is a matter of luck if the rbd metadata object belongs to incomplete pg or not (in the first case the request would get stuck, in the second it would succeed).

If we really want something like this to make sure it does not get stuck, we should check that all pgs are in 'active+...' state. And I think it is a bad idea to just return an empty list. This is misleading both for the users and for troubleshooting issues like this one. The error should be propagated and the dashboard should inform the user that currently the pool configuration is not accessible because the pool is not in healthy state.

[1] https://github.com/ceph/ceph/pull/37491
[2] https://jenkins.ceph.com/job/ceph-api/4296/
[3] https://github.com/ceph/ceph/commit/e174b91d6b7670ed575577ddff18edc354be69fb

Thanks a lot, Mykola, for the analysis. So I'll backport that suboptimal fix and raise the priority of https://tracker.ceph.com/issues/43765

If we really want something like this to make sure it does not get stuck, we should check that all pgs are in 'active+...' state. And I think it is a bad idea to just return an empty list. This is misleading both for the users and for troubleshooting issues like this one. The error should be propagated and the dashboard should inform the user that currently the pool configuration is not accessible because the pool is not in healthy state.

Fully agree. Ignoring errors is the worst way of dealing with them.

Thanks a lot for investigating and looking into the issue, Mykola!
And thanks for looking into fixing the issue, Ernesto!

Ok it seems that during the backporting from master to nautilus, a line with 'incomplete' became 'unknown'.

I'll simply backport that.

Alternative fix (proposed by Stephan): https://github.com/ceph/ceph/pull/37510

https://github.com/ceph/ceph/pull/37505 merged