Ceph » Orchestrator

Another similar scenario, which does not involve offline filesystems:

Description: rados/cephadm/smoke-roleless/{0-distro/rhel_8.4_container_tools_rhel8 0-nvme-loop 1-start 2-services/rgw-ingress 3-final}

Failure reason: hit max job timeout

Jobs:
/a/yuriw-2022-01-06_15:50:38-rados-wip-yuri8-testing-2022-01-05-1411-distro-default-smithi/6598830
/a/yuriw-2022-01-06_15:50:38-rados-wip-yuri8-testing-2022-01-05-1411-distro-default-smithi/6599155

TASK [common : Check firewalld status] *****************************************

2022-01-06T17:12:46.159 INFO:teuthology.task.ansible.out:fatal: [smithi158.front.sepia.ceph.com]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": true}
...ignoring

2022-01-06T17:12:46.180 INFO:teuthology.task.ansible.out:Thursday 06 January 2022  17:12:46 +0000 (0:00:00.236)       0:03:15.016 ****** 

2022-01-06T17:12:46.208 INFO:teuthology.task.ansible.out:
TASK [common : Open nrpe port if firewalld enabled] ****************************

TASK [testnode : Stop and disable iptables] ************************************

2022-01-06T17:16:52.036 INFO:teuthology.task.ansible.out:fatal: [smithi179.front.sepia.ceph.com]: FAILED! => {"changed": false, "msg": "Could not find the requested service iptables: host"}
...ignoring

2022-01-06T17:16:52.056 INFO:teuthology.task.ansible.out:Thursday 06 January 2022  17:16:52 +0000 (0:00:00.307)       0:07:20.893 ****** 

2022-01-06T17:16:52.698 INFO:teuthology.task.ansible.out:
TASK [testnode : Enable SELinux] ***********************************************

And a third similar scenario where an offline filesystem leads to failed CEPHADM daemons:

Description: rados/cephadm/smoke-roleless/{0-distro/ubuntu_20.04 0-nvme-loop 1-start 2-services/nfs-ingress 3-final}

Failure reason: hit max job timeout

Jobs:
/a/yuriw-2022-01-06_15:50:38-rados-wip-yuri8-testing-2022-01-05-1411-distro-default-smithi/6599055
/a/yuriw-2022-01-06_15:50:38-rados-wip-yuri8-testing-2022-01-05-1411-distro-default-smithi/6599082

2022-01-06T21:57:30.302 INFO:journalctl@ceph.mon.smithi005.smithi005.stdout:Jan 06 21:57:30 smithi005 bash[11180]: audit 2022-01-06T21:57:29.036464+0000 mon.smithi005 (mon.0) 651 : audit [INF] from='mgr.14206 172.21.15.5:0/2764321477' entity='mgr.smithi005.fpqapy' cmd=[{"prefix": "osd pool create", "pool": "cephfs.f
oofs.meta"}]: dispatch
2022-01-06T21:57:30.303 INFO:journalctl@ceph.mon.smithi005.smithi005.stdout:Jan 06 21:57:30 smithi005 bash[11180]: cluster 2022-01-06T21:57:29.125324+0000 mgr.smithi005.fpqapy (mgr.14206) 195 : cluster [DBG] pgmap v177: 1 pgs: 1 active+clean; 577 KiB data, 46 MiB used, 715 GiB / 715 GiB avail
2022-01-06T21:57:30.390 INFO:journalctl@ceph.mon.smithi031.smithi031.stdout:Jan 06 21:57:30 smithi031 bash[13845]: audit 2022-01-06T21:57:29.035515+0000 mgr.smithi005.fpqapy (mgr.14206) 194 : audit [DBG] from='client.14540 -' entity='client.admin' cmd=[{"prefix": "fs volume create", "name": "foofs", "target": ["mon-
mgr", ""]}]: dispatch
2022-01-06T21:57:30.390 INFO:journalctl@ceph.mon.smithi031.smithi031.stdout:Jan 06 21:57:30 smithi031 bash[13845]: audit 2022-01-06T21:57:29.036464+0000 mon.smithi005 (mon.0) 651 : audit [INF] from='mgr.14206 172.21.15.5:0/2764321477' entity='mgr.smithi005.fpqapy' cmd=[{"prefix": "osd pool create", "pool": "cephfs.f
oofs.meta"}]: dispatch
2022-01-06T21:57:30.390 INFO:journalctl@ceph.mon.smithi031.smithi031.stdout:Jan 06 21:57:30 smithi031 bash[13845]: cluster 2022-01-06T21:57:29.125324+0000 mgr.smithi005.fpqapy (mgr.14206) 195 : cluster [DBG] pgmap v177: 1 pgs: 1 active+clean; 577 KiB data, 46 MiB used, 715 GiB / 715 GiB avail
2022-01-06T21:57:31.136 INFO:journalctl@ceph.mon.smithi005.smithi005.stdout:Jan 06 21:57:31 smithi005 bash[11180]: debug 2022-01-06T21:57:31.045+0000 7f17651e8700 -1 log_channel(cluster) log [ERR] : Health check failed: 1 filesystem is offline (MDS_ALL_DOWN)
2022-01-06T21:57:31.136 INFO:journalctl@ceph.mon.smithi005.smithi005.stdout:Jan 06 21:57:31 smithi005 bash[11180]: audit 2022-01-06T21:57:30.036464+0000 mon.smithi005 (mon.0) 652 : audit [INF] from='mgr.14206 172.21.15.5:0/2764321477' entity='mgr.smithi005.fpqapy' cmd='[{"prefix": "osd pool create", "pool": "cephfs.foofs.meta"}]': finished

2022-01-06T21:58:40.526 INFO:teuthology.orchestra.run.smithi005.stdout:[{"placement": {"count": 1}, "service_name": "alertmanager", "service_type": "alertmanager", "status": {"created": "2022-01-06T21:51:00.275167Z", "last_refresh": "2022-01-06T21:58:38.559512Z", "ports": [9093, 9094], "running": 1, "size": 1}}, {"p
lacement": {"host_pattern": "*"}, "service_name": "crash", "service_type": "crash", "status": {"created": "2022-01-06T21:50:50.887947Z", "last_refresh": "2022-01-06T21:58:37.072722Z", "running": 2, "size": 2}}, {"placement": {"count": 1}, "service_name": "grafana", "service_type": "grafana", "status": {"created": "2
022-01-06T21:50:55.649076Z", "last_refresh": "2022-01-06T21:58:38.559719Z", "ports": [3000], "running": 1, "size": 1}}, {"events": ["2022-01-06T21:57:37.915361Z service:ingress.nfs.foo [INFO] \"service was created\""], "placement": {"count": 2}, "service_id": "nfs.foo", "service_name": "ingress.nfs.foo", "service_ty
pe": "ingress", "spec": {"backend_service": "nfs.foo", "frontend_port": 2049, "monitor_port": 9002, "virtual_ip": "10.0.31.5/16"}, "status": {"created": "2022-01-06T21:57:37.910852Z", "last_refresh": "2022-01-06T21:58:37.075244Z", "ports": [2049, 9002], "running": 3, "size": 4, "virtual_ip": "10.0.31.5/16"}}, {"even
ts": ["2022-01-06T21:57:31.078479Z service:mds.foofs [INFO] \"service was created\""], "placement": {"count": 2}, "service_id": "foofs", "service_name": "mds.foofs", "service_type": "mds", "status": {"created": "2022-01-06T21:57:31.074689Z", "last_refresh": "2022-01-06T21:58:37.074755Z", "running": 2, "size": 2}}, {
"placement": {"count": 2}, "service_name": "mgr", "service_type": "mgr", "status": {"created": "2022-01-06T21:50:48.757876Z", "last_refresh": "2022-01-06T21:58:37.073083Z", "running": 2, "size": 2}}, {"placement": {"count": 2, "hosts": ["smithi005:172.21.15.5=smithi005", "smithi031:172.21.15.31=smithi031"]}, "servic
e_name": "mon", "service_type": "mon", "status": {"created": "2022-01-06T21:51:55.847078Z", "last_refresh": "2022-01-06T21:58:37.073332Z", "running": 2, "size": 2}}, {"events": ["2022-01-06T21:57:37.910505Z service:nfs.foo [INFO] \"service was created\""], "placement": {"count": 2}, "service_id": "foo", "service_nam
e": "nfs.foo", "service_type": "nfs", "spec": {"port": 12049}, "status": {"created": "2022-01-06T21:57:37.905948Z", "last_refresh": "2022-01-06T21:58:37.075048Z", "ports": [12049], "running": 2, "size": 2}}, {"placement": {"host_pattern": "*"}, "service_name": "node-exporter", "service_type": "node-exporter", "statu
s": {"created": "2022-01-06T21:50:58.088177Z", "last_refresh": "2022-01-06T21:58:37.073559Z", "ports": [9100], "running": 2, "size": 2}}, {"events": ["2022-01-06T21:53:27.529310Z service:osd.all-available-devices [INFO] \"service was created\""], "placement": {"host_pattern": "*"}, "service_id": "all-available-devic
es", "service_name": "osd.all-available-devices", "service_type": "osd", "spec": {"data_devices": {"all": true}, "filter_logic": "AND", "objectstore": "bluestore"}, "status": {"created": "2022-01-06T21:53:27.522984Z", "last_refresh": "2022-01-06T21:58:37.073802Z", "running": 8, "size": 8}}, {"placement": {"count": 1
}, "service_name": "prometheus", "service_type": "prometheus", "status": {"created": "2022-01-06T21:50:53.020786Z", "last_refresh": "2022-01-06T21:58:38.559921Z", "ports": [9095], "running": 1, "size": 1}}]
2022-01-06T21:58:40.982 INFO:journalctl@ceph.mon.smithi031.smithi031.stdout:Jan 06 21:58:40 smithi031 bash[13845]: cluster 2022-01-06T21:58:39.567636+0000 mon.smithi005 (mon.0) 747 : cluster [WRN] Health check failed: 1 failed cephadm daemon(s) (CEPHADM_FAILED_DAEMON)
2022-01-06T21:58:41.053 INFO:journalctl@ceph.mon.smithi005.smithi005.stdout:Jan 06 21:58:40 smithi005 bash[11180]: cluster 2022-01-06T21:58:39.567636+0000 mon.smithi005 (mon.0) 747 : cluster [WRN] Health check failed: 1 failed cephadm daemon(s) (CEPHADM_FAILED_DAEMON)
2022-01-06T21:58:41.698 INFO:tasks.cephadm:nfs.foo has 2/2

Jeff Layton wrote:

Looking at /a/yuriw-2022-01-06_15:50:38-rados-wip-yuri8-testing-2022-01-05-1411-distro-default-smithi/6599082/remote/smithi137/log/6ffb065c-6f3e-11ec-8c32-001a4aab830c

[...]

There's a more recent log too, but it's scrambled. The is_rank_lagging message may be significant here, but it looks like it started up, and was running until it was shut down (probably via systemd).

is_rank_lagging should be harmless - that's a part of the metrics machinery in the MDS that does not effect the MDSs boot procedure.

The other job (6599055) looks similar, there is just no log message about a SIGHUP.

Is this related to CephFS? Comment https://tracker.ceph.com/issues/53807#note-1 indicates this is being hit with rados jobs too.

Moved this Tracker out of CephFS, as offline filesystems on this particular test appear even in successful runs.

Example successful run: /a/yuriw-2022-01-04_18:45:05-rados-wip-yuriw-master-1.1.22-distro-default-smithi/6595039

2022-01-04T21:05:24.444 INFO:journalctl@ceph.mon.smithi149.smithi149.stdout:Jan 04 21:05:23 smithi149 ceph-mon[29224]: from='mgr.14214 172.21.15.149:0/4025601137' entity='mgr.smithi149.axflmp' cmd=[{"prefix": "osd pool create", "pool": "cephfs.foofs.data"}]: dispatch
2022-01-04T21:05:24.445 INFO:journalctl@ceph.mon.smithi149.smithi149.stdout:Jan 04 21:05:23 smithi149 conmon[29200]: 2022-01-04T21:05:23.994+0000 7f2cefb7c700 -1 log_channel(cluster) log [ERR] : Health check failed: 1 filesystem is offline (MDS_ALL_DOWN)
2022-01-04T21:05:25.034 DEBUG:teuthology.orchestra.run.smithi149:> sudo /home/ubuntu/cephtest/cephadm --image quay.ceph.io/ceph-ci/ceph:7b5bbfea3dc99d59b2173c093177ae92f881f823 shell -c /etc/ceph/ceph.conf -k /etc/ceph/ceph.client.admin.keyring --fsid 15c89698-6da1-11ec-8c32-001a4aab830c -- bash -c 'ceph nfs cluster create foo --ingress --virtual-ip 10.0.31.149/16 --port 2999'

Hidden Ansible output is also normal. The root of the cause must be something else:

TASK [common : Check firewalld status] *****************************************

2022-01-04T20:51:41.958 INFO:teuthology.task.ansible.out:fatal: [smithi149.front.sepia.ceph.com]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": true}
...ignoring

2022-01-04T20:51:41.979 INFO:teuthology.task.ansible.out:Tuesday 04 January 2022  20:51:41 +0000 (0:00:00.081)       0:03:15.747 ******* 

2022-01-04T20:51:42.016 INFO:teuthology.task.ansible.out:
TASK [common : Open nrpe port if firewalld enabled] ****************************

/a/yuriw-2022-01-13_18:06:52-rados-wip-yuri3-testing-2022-01-13-0809-distro-default-smithi/6614725
/a/yuriw-2022-01-13_18:06:52-rados-wip-yuri3-testing-2022-01-13-0809-distro-default-smithi/6614681
/a/yuriw-2022-01-13_18:06:52-rados-wip-yuri3-testing-2022-01-13-0809-distro-default-smithi/6614665

fix is in pacific now via https://github.com/ceph/ceph/pull/44628. Quincy backport is in testing https://github.com/ceph/ceph/pull/45038

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