Fedora Account System
Red Hat Associate
Red Hat Customer
The PGs are unclean, which is causing the 10 min per OSD. This is by design. For example, the operator log shows. 2020-05-27 12:41:33.653447 I | util: retrying after 1m0s, last error: cluster is not fully clean. PGs: [{StateName:active+recovery_wait+remapped Count:92} {StateName:active+undersized+degraded+remapped+backfill_wait Count:38} {StateName:active+recovery_wait+undersized+degraded+remapped Count:37} {StateName:active+recovery_wait Count:32} {StateName:active+clean Count:23} {StateName:active+remapped+backfill_wait Count:20} {StateName:active+recovery_wait+degraded+remapped Count:18} {StateName:active+undersized+remapped+backfill_wait Count:2} {StateName:active+recovering+undersized+degraded+remapped Count:1} {StateName:active+recovery_wait+degraded Count:1}] 2020-05-27 12:42:34.027843 I | op-mon: The osd daemon 4 is not ok-to-stop but 'continueUpgradeAfterChecksEvenIfNotHealthy' is true, so continuing...
I ran again the upgrade job and noticed this: 18:39:14 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Installing! 18:39:14 - MainThread - ocs_ci.utility.utils - INFO - Going to sleep for 5 seconds before next iteration 18:39:15 - Thread-2 - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig rsh rook-ceph-tools-6f59b98f4f-fg8w7 ceph health detail 18:39:19 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml 18:39:20 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Installing! 18:39:20 - MainThread - ocs_ci.utility.utils - INFO - Going to sleep for 5 seconds before next iteration 18:39:21 - Thread-2 - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig rsh rook-ceph-tools-6f59b98f4f-fg8w7 ceph health detail 18:39:25 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml 18:39:26 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Failed! 18:39:26 - MainThread - ocs_ci.utility.utils - INFO - Going to sleep for 5 seconds before next iteration 18:39:27 - Thread-2 - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig rsh rook-ceph-tools-6f59b98f4f-fg8w7 ceph health detail 18:39:31 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml 18:39:32 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Failed! 19:08:57 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml 19:08:57 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Failed! 19:08:57 - MainThread - ocs_ci.utility.utils - INFO - Going to sleep for 5 seconds before next iteration 19:09:01 - Thread-2 - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig rsh rook-ceph-tools-6f59b98f4f-fg8w7 ceph health detail 19:09:02 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml 19:09:03 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Failed! 19:09:03 - MainThread - ocs_ci.utility.utils - INFO - Going to sleep for 5 seconds before next iteration 19:09:07 - Thread-2 - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig rsh rook-ceph-tools-6f59b98f4f-fg8w7 ceph health detail 19:09:08 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml 19:09:09 - MainThread - ocs_ci.ocs.ocp - INFO - Resource ocs-operator.v4.4.0-437.ci is in phase: Failed! When I connected to the cluster later on the CSV was ok in Succeed state. Job: https://ocs4-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/job/qe-deploy-ocs-cluster/8159/consoleFull Which means CSV was in Failed state. We need to check how it looks from UI if it's visible somehow to the user which can think of the upgrade went wrong. Travis do you think this status is visible somewhere in the UI? Must gathers from different test failures are here: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-pr2176-b1892/jnk-pr2176-b1892_20200527T160810/logs/failed_testcase_ocs_logs_1590598530/ The one which was taken right after OCS upgrade test failed is here: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-pr2176-b1892/jnk-pr2176-b1892_20200527T160810/logs/failed_testcase_ocs_logs_1590598530/test_upgrade_ocs_logs/ But another must gather was taken later one here on different failure: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-pr2176-b1892/jnk-pr2176-b1892_20200527T160810/logs/failed_testcase_ocs_logs_1590598530/test_noobaa_postupgrade_ocs_logs/
> Which means CSV was in Failed state. We need to check how it looks from UI if it's visible somehow to the user which can think of the upgrade went wrong. > Travis do you think this status is visible somewhere in the UI? Is the ocs-operator.v4.4.0-437.ci a StorageCluster CR? If it is in failed state I assume the failed status would show up in the UI. @Jose can you confirm?
It is CSV, you can see we get those data in console output I pasted: get csv ocs-operator.v4.4.0-437.ci -n openshift-storage -o yaml I see that operator is still not running 0/1 : ocs-operator-748956487-xjpg7 0/1 Running 0 40m 10.129.2.42 ip-10-0-146-135.us-east-2.compute.internal <none> <none> http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-pr2176-b1892/jnk-pr2176-b1892_20200527T160810/logs/failed_testcase_ocs_logs_1590598530/test_upgrade_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-823e0fb90bb272997746eb4923463cef597cc74818cd9050f791b64df4f2c9b2/oc_output/get%20pods%20-owide But not sure how this is propagated to UI.
As this wasn't observed in 4.2 to 4.3 upgrade is that a regression?
We didn't have add capacity test enabled in upgrade before so we didn't executed production upgrade job on 6 OSDs. But Filip tried today ran the upgrade from 4.2 to 4.3 and ocs upgrade test failed on the same here. So I guess this issue was there already before but we didn't test it.
Thanks Petr
I'm willing to bet this does get displayed to the user if they go looking, probably under the Installed Operators modal. Even so, I think this is the OLM working as designed. The CSV is indeed failing until the operator reports it is Ready. And we are accurately reporting that we are not Ready until all components are healthy. I'm not sure there's much to be done about that, though I could be wrong. We could ask the OLM team what they think of this, but I say we should do that without holding the release.
Shylesh this wasn't the same case as I reported. This is normal and I saw that couple of times . But my issue was that OSDs got upgraded I was for more than 20 mins in this Failed state. Maybe someone from OLM can take a look and tell us if there is better approach than have Failed state of CSV if upgrade is still processing.
Hi folks, So on the OLM side, there is a timeout of 5 minutes for installing/upgrading process (aka pending state). When a CSV is in pending state for more than 5 minutes, the status will be switched over to Failed if all installation requirements haven't been met (for example, the deployment pod is not ready and etc). Later on, the CSV status will be switched back to Pending when OLM attempt to check the conditions of installation/upgrade again. It seems for OCS, the upgrading process is taking significantly longer than the 5 minutes timeout which leads to the status being switching back and forth between pending and failed until the upgrade is finally competed. This may cause some confusion on the UI from users' perspective. I'm not sure how to rectify this issue given OLM doesn't know if the upgrade is still progressing or actually being stuck. It needs to switch the status to Failed eventually. Being stuck in pending state for over an hour is just as confusing as the status being switching back and forth. I wonder if there is a way for OCS to speed up the upgrade process. Thanks, Vu
I ran on cluster with 3 OSDS only without add capacity. This time I haven't seen such issue and OSDs got upgraded relatively quick. ~30 seconds between. rook-ceph-osd-0-bf7c58dfc-7phz8 1/1 Running 0 7m22s rook-ceph-osd-1-58cc6c4bc5-tgznl 1/1 Running 0 6m59s rook-ceph-osd-2-6877f5b8c6-dbszl 1/1 Running 0 6m29s From logs as we do in parallel health check I see 08:56:26,264: 2020-05-29 08:56:26,264 - DEBUG - ocs_ci.utility.utils.exec_cmd.446 - Command stdout: HEALTH_WARN 1 osds down; 1 host (1 osds) down; 1 zone (1 osds) down; Degraded data redundancy: 27749/151998 objects degraded (18.256%), 68 pgs degraded OSD_DOWN 1 osds down osd.0 (root=default,region=us-east-2,zone=us-east-2b,host=ocs-deviceset-0-0-z85l2) is down OSD_HOST_DOWN 1 host (1 osds) down host ocs-deviceset-0-0-z85l2 (root=default,region=us-east-2,zone=us-east-2b) (1 osds) is down OSD_ZONE_DOWN 1 zone (1 osds) down zone us-east-2b (root=default,region=us-east-2) (1 osds) is down PG_DEGRADED Degraded data redundancy: 27749/151998 objects degraded (18.256%), 68 pgs degraded 2 seconds later I see that OSD pod still doesn't have upgraded image 2020-05-29 08:56:28,250 - WARNING - ocs_ci.ocs.resources.pod.verify_pods_upgraded.1256 - Images: {'registry.redhat.io/rhceph/rhceph-4-rhel8@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d'} weren't upgraded in: rook-ceph-osd-0-7dd44896cc-x55cp! Another 2 seconds later pod rook-ceph-osd-0-7dd44896cc-x55cp got probably restarted as is not available here: 2020-05-29 08:56:30,788 - WARNING - ocs_ci.ocs.resources.pod.verify_pods_upgraded.1252 - Failed when getting pods with selector app=rook-ceph-osd.Error: Error during execution of command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get Pod rook-ceph-osd-0-7dd44896cc-x55cp -n openshift-storage -o yaml. Error is Error from server (NotFound): pods "rook-ceph-osd-0-7dd44896cc-x55cp" not found 6 sec later I see new OSD 0 pod rook-ceph-osd-0-bf7c58dfc-7phz8 : 2020-05-29 08:56:36,173 - INFO - ocs_ci.utility.utils.exec_cmd.433 - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get Pod rook-ceph-osd-0-bf7c58dfc-7phz8 -n openshift-storage -o yaml Already has new image: - name: CONTAINER_IMAGE value: quay.io/rhceph-dev/rhceph@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d So in this case we saw that OSD pod got upgraded/restarted even if the cluster was in degraded state. Log: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-pr2184-b1901/jnk-pr2184-b1901_20200529T063120/logs/ocs-ci-logs-1590736448/tests/ecosystem/upgrade/test_upgrade.py/test_upgrade/logs Jenkins job: https://ocs4-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/job/qe-deploy-ocs-cluster/8199/consoleFull
To be clear, we can't always speed up the upgrade. As the data platform we need to do everything possible to keep a stable data plane even during the upgrade. If we skip the upgrade checks to speed up the upgrade, we will be putting that at risk. But I wouldn't expect it to be common for the cluster to be unhealthy during upgrade. How often is this even seen? The solution will need to include improving of the upgrade status reporting.
Created attachment 1695377 [details] rook-ceph-operator-log after upgrade
Travis in reply to: How often is this even seen? This happen quite often in our upgrade test job, would say that in latest executions we saw it almost always. We can trigger some upgrade job during next week for you so you can take a look during the upgrade on the cluster. WDYT?
(In reply to Petr Balogh from comment #18) > Travis in reply to: How often is this even seen? > > This happen quite often in our upgrade test job, would say that in latest > executions we saw it almost always. > > We can trigger some upgrade job during next week for you so you can take a > look during the upgrade on the cluster. > > WDYT? It is clear from the logging that the upgrade is delayed because of unclean PGs. The behavior is expected under that condition. My question about the frequency is about how often customers would hit it. They wouldn't normally have unclean PGs.
So looking through this, it seems that this is all expected behavior, is that right? If so, do we have anything to fix or do the tests need to be modified? And in either case, is it something urgent enough for an OCS 4.4.z release?
@travis, is that 1- minute timeout somehow hardcoded that it always wait for 10 mins till restarting next OSD? Or it does check also in between like each x seconds to check status of PGs? Just curious if PGs got clean in 3 mins if we still waiting 10 mins? If so this should check periodically and restart pod sooner to speed up the upgrade. If it already does than is this anything we can fix to speed up process or this is expected behavior and not a bug? Thanks
I don't think that if something needs to be handled here nothing urgent which can wait till 4.5 if decided something to fix here.
@Petr Yes, rook will check once per minute if the PGs are clean and the upgrade can continue. Before the upgrade is started, are the PGs clean? If they are clean, I would expect the upgrade to happen quickly. If they aren't clean to start with, it can make the upgrade unpredictable like this.
Still sounds like this is working as designed. I think Travis had a needinfo on @Petr.
Travis, I am pretty sure that we have ceph cluster in health state before upgrade. 11:50:36 - MainThread - ocs_ci.utility.utils - INFO - Ceph cluster health is HEALTH_OK. 11:50:36 - MainThread - tests.conftest - INFO - Ceph health check passed at teardown tests/ecosystem/upgrade/test_upgrade.py::test_upgrade https://ocs4-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/job/qe-deploy-ocs-cluster/8123/consoleFull If PGs are not clean I think we will not heave HEALTH_OK but WARN . Even though once the upgrade start and one OSD get's restarted it probably will make PGs not to be clean and then take ~10 mins for other OSD to be restarted. There is running some workload in the background when we do this upgrade but as I said, cluster should be healthy with clean PGs. From debug log of execution: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/ocs-ci-logs-1590574577/by_outcome/failed/tests/ecosystem/upgrade/test_upgrade.py/test_upgrade/logs From time: 11:52:24 I see that even just before we patch channel to new version it was HEALTH_OK . and upgrade itself happen here: 11:52:27 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc patch subscription ocs-subscription -n openshift-storage --type merge -p '{"spec":{"channel": "stable-4.4", "source": "ocs-catalogsource"}}' 11:52:27 - MainThread - test_upgrade - INFO - Attempt 1/145 to check CSV upgraded. 11:52:27 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-marketplace --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get packagemanifest -n openshift-marketplace --selector=ocs-operator-internal=true -o yaml 11:52:28 - MainThread - test_upgrade - INFO - CSV now upgraded to: ocs-operator.v4.4.0-437.ci 3 seconds later but still we see this 10 mins between all OSDs . If you told that: If they are clean, I would expect the upgrade to happen quickly. This is not the case here and we reproduced many times already and I think we need to identify the issue here why this is taking that long even if PGs are cleaned before upgrade. Thanks
@Petr These are my observations in your log: - The OSDs are all upgraded after about two minutes. - The last HEALTH_OK messages is at 11:53:50 - The HEALTH_WARN messages sequence is: 11:53:56 osd.1 is down 11:54:20 osd.3 is down 11:54:51 osd.2 is down 11:55:21 osd.4 is down 11:55:39 osd.0 is down 11:56:03 osd.5 is down - After 11:56:10 there is a consistent HEALTH_WARN - The PGs show in recovery state such as: active+recovery_wait+degraded - A few times other OSDs go down briefly. Are nodes being restarted or other actions to take down OSDs? So where do you see that the OSDs are taking 10 minutes each to upgrade? From my observation it was only a period of just over two minutes total for all OSDs to go down and come back up. But this is a huge log. Is there a different place to look in the log?
Hey Travis, From test console output here: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/deploy-ocs-cluster-build-1590595348.log I see: 12:00:29 - MainThread - ocs_ci.ocs.resources.pod - INFO - Found 6 pod(s) for selector: app=rook-ceph-osd 12:00:29 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get Pod rook-ceph-osd-0-657f8848bd-6cfqq -n openshift-storage -o yaml 12:00:29 - MainThread - ocs_ci.ocs.resources.pod - WARNING - Images: {'registry.redhat.io/rhceph/rhceph-4-rhel8@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d'} weren't upgraded in: rook-ceph-osd-0-657f8848bd-6cfqq! 12:00:29 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get Pod -n openshift-storage -o yaml 12:00:33 - MainThread - ocs_ci.ocs.resources.pod - INFO - Found 6 pod(s) for selector: app=rook-ceph-osd 30 Mins later I see the same error: 12:30:26 - MainThread - ocs_ci.ocs.resources.pod - INFO - Found 6 pod(s) for selector: app=rook-ceph-osd 12:30:26 - MainThread - ocs_ci.utility.utils - INFO - Executing command: oc -n openshift-storage --kubeconfig /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get Pod rook-ceph-osd-0-657f8848bd-6cfqq -n openshift-storage -o yaml 12:30:27 - MainThread - ocs_ci.ocs.resources.pod - WARNING - Images: {'registry.redhat.io/rhceph/rhceph-4-rhel8@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d'} weren't upgraded in: rook-ceph-osd-0-657f8848bd-6cfqq! But image in osd 1 I see here: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/failed_testcase_ocs_logs_1590574577/test_upgrade_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-823e0fb90bb272997746eb4923463cef597cc74818cd9050f791b64df4f2c9b2/oc_output/describe%20pods Got already changed to quay.io/rhceph-dev/rhceph@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d but in OSD1 there is still old image. Which points me that container is not properly upgraded if it does not contain the image which is defined in new CSV for new build. I see that image has the same SHA sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d . But image location is different, which I am not sure if can cause some issue, but if CSV contains the image from different location I guess that pod/container should use the new one image and I see that after some time each of OSD finally got restarted and have the proper image from quay and not registry.redhat.io. Thanks
I still don't see where the 10 minute timeout is getting hit. Can you point me to the operator log that would show where the osds are getting upgraded? I'm getting lost in all the test logs. :)
If you will look at the must gather just after upgrade test failed I see in this oc command: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/failed_testcase_ocs_logs_1590574577/test_upgrade_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-823e0fb90bb272997746eb4923463cef597cc74818cd9050f791b64df4f2c9b2/oc_output/get%20pods%20-owide This: rook-ceph-osd-0-657f8848bd-6cfqq 1/1 Running 0 35m 10.131.0.45 ip-10-0-161-81.us-east-2.compute.internal <none> <none> rook-ceph-osd-1-74dc885d8d-j7fhm 1/1 Running 1 30m 10.128.2.49 ip-10-0-143-82.us-east-2.compute.internal <none> <none> rook-ceph-osd-2-5b49887f4b-trw27 1/1 Running 2 9m 10.129.2.43 ip-10-0-149-200.us-east-2.compute.internal <none> <none> rook-ceph-osd-3-6464697d6b-xtzlr 1/1 Running 0 19m 10.128.2.50 ip-10-0-143-82.us-east-2.compute.internal <none> <none> rook-ceph-osd-4-8595c694fc-rsdzp 1/1 Running 0 35m 10.129.2.39 ip-10-0-149-200.us-east-2.compute.internal <none> <none> rook-ceph-osd-5-59646789b6-x7q87 1/1 Running 0 34m 10.131.0.46 ip-10-0-161-81.us-east-2.compute.internal <none> <none> So I see that time between some OSD pods is like those 10 mins differences: 9m, 19m, 35m, but I think that pods which has 35 or 34 are not restarted yet with new image. We are checking that all pods have already new image but we get stuck on fist pod rook-ceph-osd-0 as I pointed out in the logs in comment 30 . Must gather collected right after failed test case - which failed to verify osd-0 pod to be upgraded. All OCP and OCS must gather is here: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/failed_testcase_ocs_logs_1590574577/test_upgrade_ocs_logs/ OCS operator logs should be here if I am right: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/failed_testcase_ocs_logs_1590574577/test_upgrade_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-823e0fb90bb272997746eb4923463cef597cc74818cd9050f791b64df4f2c9b2/ceph/namespaces/openshift-storage/pods/ocs-operator-748956487-vdlfs/ocs-operator/ocs-operator/logs/current.log And here I don't see any mentioned word osd. Not sure where else to look for information about OSDs getting upgraded? But this time when we failed test for sure few of the pods didn't get updraded image which I consider as pod didn't get upgraded properly yet which I can see from this describe from must gather: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-ai3c33-ua/jnk-ai3c33-ua_20200527T092741/logs/failed_testcase_ocs_logs_1590574577/test_upgrade_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-823e0fb90bb272997746eb4923463cef597cc74818cd9050f791b64df4f2c9b2/oc_output/describe%20pods as I pointed in previous comment.
Ok, now I see from the operator log the following rook daemon updates: $ grep "updating deployment" op.log 2020-05-27T11:53:28.947500916Z 2020-05-27 11:53:28.947469 I | op-k8sutil: updating deployment rook-ceph-mon-a 2020-05-27T11:53:31.396048372Z 2020-05-27 11:53:31.396026 I | op-k8sutil: updating deployment rook-ceph-mon-b 2020-05-27T11:53:33.864286388Z 2020-05-27 11:53:33.864075 I | op-k8sutil: updating deployment rook-ceph-mon-c 2020-05-27T11:53:40.823026882Z 2020-05-27 11:53:40.822996 I | op-k8sutil: updating deployment rook-ceph-mgr-a 2020-05-27T11:53:54.654918413Z 2020-05-27 11:53:54.654883 I | op-k8sutil: updating deployment rook-ceph-osd-1 2020-05-27T11:54:12.213817283Z 2020-05-27 11:54:12.213778 I | op-k8sutil: updating deployment rook-ceph-osd-3 2020-05-27T11:54:43.869190092Z 2020-05-27 11:54:43.869157 I | op-k8sutil: updating deployment rook-ceph-osd-2 2020-05-27T11:55:11.444495095Z 2020-05-27 11:55:11.444454 I | op-k8sutil: updating deployment rook-ceph-osd-4 2020-05-27T11:55:30.949599282Z 2020-05-27 11:55:30.949563 I | op-k8sutil: updating deployment rook-ceph-osd-0 2020-05-27T11:55:50.460574519Z 2020-05-27 11:55:50.460540 I | op-k8sutil: updating deployment rook-ceph-osd-5 2020-05-27T11:56:17.865164913Z 2020-05-27 11:56:17.865129 I | op-k8sutil: updating deployment rook-ceph-mds-ocs-storagecluster-cephfilesystem-a 2020-05-27T11:56:22.858385246Z 2020-05-27 11:56:22.858347 I | op-k8sutil: updating deployment rook-ceph-mds-ocs-storagecluster-cephfilesystem-b 2020-05-27T11:56:27.763956645Z 2020-05-27 11:56:27.763939 I | op-k8sutil: updating deployment rook-ceph-mon-a 2020-05-27T11:58:00.177707735Z 2020-05-27 11:58:00.177691 I | op-k8sutil: updating deployment rook-ceph-mon-b 2020-05-27T11:59:38.501185595Z 2020-05-27 11:59:38.501166 I | op-k8sutil: updating deployment rook-ceph-mon-c 2020-05-27T12:00:09.725932877Z 2020-05-27 12:00:09.725893 I | op-k8sutil: updating deployment rook-ceph-mgr-a 2020-05-27T12:00:34.379815864Z 2020-05-27 12:00:34.379811 I | op-k8sutil: updating deployment rook-ceph-osd-1 2020-05-27T12:10:59.244420428Z 2020-05-27 12:10:59.244416 I | op-k8sutil: updating deployment rook-ceph-osd-3 2020-05-27T12:21:36.01474898Z 2020-05-27 12:21:36.014743 I | op-k8sutil: updating deployment rook-ceph-osd-2 In my previous investigation I had focused on the first set of restarts where the OSDs were all updated between 11:53:54 and 11:55:50. I see that the upgrade in question starts at 12:00:34, and that the OSDs are only updated about every 10 minutes after the timeout. In the test log, the last HEALTH_OK message I see is at 11:53:50, before the first time the OSDs start upgrading. Interesting to note is that the second round of upgrades is triggered by an update to the ceph image: 2020-05-27T11:56:13.288989487Z 2020-05-27 11:56:13.288956 I | op-cluster: The Cluster CR has changed. diff={v1.ClusterSpec}.CephVersion.Image: 2020-05-27T11:56:13.288989487Z -: "registry.redhat.io/rhceph/rhceph-4-rhel8@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d" 2020-05-27T11:56:13.288989487Z +: "quay.io/rhceph-dev/rhceph@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d" Was that update intended? The hash is the same, but the registry is different. I still don't see from the logs why the PGs remain unclean through the second upgrade, but can we avoid the second upgrade?
Since it seems we have determined this is a PG issue, moving this under the rook component.
@Travis, What do you mean by: I still don't see from the logs why the PGs remain unclean through the second upgrade, but can we avoid the second upgrade? I didn't get about what upgrade are you talking? We are performing only one upgrade from one version to the other. Those images below I referred in few of my comments like: https://bugzilla.redhat.com/show_bug.cgi?id=1840729#c30 : 2020-05-27T11:56:13.288989487Z -: "registry.redhat.io/rhceph/rhceph-4-rhel8@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d" 2020-05-27T11:56:13.288989487Z +: "quay.io/rhceph-dev/rhceph@sha256:9e521d33c1b3c7f5899a8a5f36eee423b8003827b7d12d780a58a701d0a64f0d" The thing is that DS build in CSV points to quay. Instead of previous version installed from live GAed version pointing to registry.redhat.io . I got confirmation engineering that the image is the same. But I see different name and different location but SHA is the same. Not sure if it can make some confusion/troubles to operator? But when the image is different in CSV I expect to have the pods restarted with that exact image which is defined in the CSV. Petr
Ok, what appears to Rook to be "two upgrades" is only a single OCS upgrade. The first upgrade is where the Rook operator image is applied. The second upgrade is for the Ceph image update. The sequence is: 1. Update the CSV. The OCS and Rook operators are restarted with their new images. 2. The Rook operator starts a reconcile of all the ceph daemons. This is the first Rook upgrade. The daemons that have the rook image in the pod spec are all restarted, including the OSDs. This restart of the OSDs is successful since the PGs are still clean. 3. At the same time as #2, the OCS operator starts a reconcile and updates the CephCluster with the new image. Rook will not reconcile this new image until step #2 is completed. 4. The Rook operator starts the second reconcile because the CephCluster CR was updated. The OSDs are updated for the second time because of the new image. The PGs are not clean at this point, which means there is a 10 minute delay between each OSD update. To answer my own question, you don't have a way to skip the "second upgrade". Your tests are running on 4.4, right? Have you tested on 4.5? In 4.5, we actually have an improvement that would allow the OSD upgrade to be skipped during step #2, which means it will truly be a single upgrade for the OSDs. Hopefully in 4.5 this will no longer be an issue. However, this still doesn't answer the question of why the PGs are unclean during #4.
Yes we were running upgrade from 4.3 to 4.4. Currently the 4.5 is broken and we cannot even install it, so I haven't tried the upgrade yet. Once we will have some deployable OCS 4.5 build I can try on that. However, this still doesn't answer the question of why the PGs are unclean during #4. Is this cause of 1st restart of the OSDs - as we are running some IO in the background during this that after restart we will get to the situation that PGs are unclean?
The IO running during the upgrade could cause degraded PGs temporarily, but unless you have a very high load I would expect them to recover fairly quickly instead of staying in unclean states. The data load isn't very big, right? If any OSDs go down it would affect the PG health, but it didn't appear to me in the logs that OSDs went down again after the first upgrade.
To clarify on next steps from my perspective: - I moved this out of 4.4 since we can't expect a fix for the double upgrade step in 4.4 - In 4.5, in general the double upgrade issue is fixed so there is only a single upgrade now. - However, if in a particular release Rook updates the OSD pod spec, there will again be a double upgrade just for that release. - Investigation is still needed for why the PGs are not healthy during the second upgrade - If QE does not see this as a blocking issue for 4.5, let's move to 4.6. @Petr what is your view on adding the blocking flag?
For Comment #41 PGs went to unclean state since upgrade of first osd , i.e. osd-1 (as they took >10 mins to come to CLEAN state due to ongoing FIO) > Ceph status before osd-5 upgraded , thus PGs were UNCLEAN because of an OSD updated 9mins back(6 osds: 6 up (since 9m)), still osd-5 upgrade starts after 1 mins =====ceph status ==== Tue Jul 7 08:00:02 UTC 2020 cluster: id: 4ce5142d-bc43-409c-8bd3-59690bfb487e health: HEALTH_WARN Degraded data redundancy: 128/125994 objects degraded (0.102%), 19 pgs degraded, 1 pg undersized services: mon: 3 daemons, quorum a,b,c (age 34m) mgr: a(active, since 32m) mds: ocs-storagecluster-cephfilesystem:1 {0=ocs-storagecluster-cephfilesystem-a=up:active} 1 up:standby-replay osd: 6 osds: 6 up (since 9m), 6 in (since 15h); 4 remapped pgs rgw: 1 daemon active (ocs.storagecluster.cephobjectstore.a) task status: scrub status: mds.ocs-storagecluster-cephfilesystem-a: idle mds.ocs-storagecluster-cephfilesystem-b: idle data: pools: 10 pools, 360 pgs objects: 42.00k objects, 159 GiB usage: 479 GiB used, 2.5 TiB / 3.0 TiB avail pgs: 128/125994 objects degraded (0.102%) 16/125994 objects misplaced (0.013%) 337 active+clean 15 active+recovery_wait+degraded 3 active+recovery_wait 2 active+recovery_wait+degraded+remapped 1 active+recovery_wait+undersized+degraded+remapped 1 active+recovering+degraded 1 active+recovery_wait+remapped io: client: 54 KiB/s rd, 2.1 MiB/s wr, 15 op/s rd, 15 op/s wr recovery: 795 KiB/s, 0 objects/s >> Ceph status when osd-5 update started Tue Jul 7 08:00:15 UTC 2020 cluster: id: 4ce5142d-bc43-409c-8bd3-59690bfb487e health: HEALTH_WARN 1 osds down 1 host (1 osds) down Degraded data redundancy: 21235/126003 objects degraded (16.853%), 110 pgs degraded services: mon: 3 daemons, quorum a,b,c (age 34m) mgr: a(active, since 33m) mds: ocs-storagecluster-cephfilesystem:1 {0=ocs-storagecluster-cephfilesystem-a=up:active} 1 up:standby-replay osd: 6 osds: 5 up (since 11s), 6 in (since 15h); 12 remapped pgs rgw: 1 daemon active (ocs.storagecluster.cephobjectstore.a) task status: scrub status: mds.ocs-storagecluster-cephfilesystem-a: idle mds.ocs-storagecluster-cephfilesystem-b: idle data: pools: 10 pools, 360 pgs objects: 42.00k objects, 159 GiB usage: 479 GiB used, 2.5 TiB / 3.0 TiB avail pgs: 1.111% pgs not active 21235/126003 objects degraded (16.853%) 20/126003 objects misplaced (0.016%) 177 active+clean 90 active+undersized+degraded 66 active+undersized 11 active+recovery_wait+degraded 5 active+recovery_wait+degraded+remapped 3 remapped+peering 2 active+recovery_wait+undersized+degraded 2 active+clean+remapped 1 active+recovering+degraded 1 active+recovery_wait+remapped 1 active+recovering+undersized+degraded 1 activating+remapped io: client: 753 KiB/s wr, 0 op/s rd, 14 op/s wr recovery: 2.8 MiB/s, 0 objects/s
Hey Travis, > - If QE does not see this as a blocking issue for 4.5, let's move to 4.6. @Petr what is your view on adding the blocking flag? From my perspective of view, the user can see the OCS operator in failed state if the upgrade take that long time which is this case as described in comment: https://bugzilla.redhat.com/show_bug.cgi?id=1840729#c13 This is bad user experience which can lead to confusion about the upgrade but not sure if we can fix this from OCS point of view as it's OLM behavior. This can be fixed only if the upgrade will not take that long time, or there will be some OLM fix added to enable show that upgrade is still in the progress and not show OCS operator as failed. @vu can maybe add his point of view if he thinks this can be somehow fixed from OLM point of view to give OCS more time for upgrade and show correct status of upgrading/installing or something better than failed. If you think that the issue should be already fixed in 4.5 I would like to have this fixed there, but from what I understand from @Neha's reply that the PGs are uncleaned after first upgrade anyway, so not sure if it's gonna be fixed by double upgrade fix you are talking about. Thanks Neha for pointing out all the details!
Hey folks, Currently, the timeout for pending state is 5 mins. After that, CSV will be transitioned to failed state. We can technically increase this timeout to be longer but eventually CSV will still reach failed state if the upgrade process is taking too long. It is also a bad user experience when the CSV is stuck in pending state and cannot progress further due to long timeout. Do you have a statistics on how long OCS is taking to upgrade successfully? @Evan Do you think we should increase the timeout?
Vu, it depends on how many OCS the cluster has. In our case 6 OSDs it took about 1 hour or so 6* 10 min per OSD based on this BZ. There can be even more OSDs on the cluster and can take even more. OSD_COUNT*10 mins. I was thinking if OCS can somehow tell the operator that it is still upgrading to have this correct state propagated to OLM instead of just increase timeout. Or calculate the timeout based on number of OSDs for OCS but will be better to have real status from OCS operator.
Hey Petr, It would be great to have the operator telling OLM about the upgrade progress instead of OLM is doing the guess-work. I think we have an epic in the pipeline for the upgrade status. However, at the moment, there is no mechanism to let the operator telling OLM about upgrade progress unfortunately. So the timeout will still play an important role here for the status changing.
> As per Seb "the first one with ROOK_CEPH_IMAGE is due a legacy design that does not exist anymore on fresh new deployments. The other one on CEPH_IMAGE will be treated as an upgrade correctly and Rook will wait between each OSDs. I don't think eng is planning on fixing the former."" @Neha Agreed, this is a legacy behavior I keep forgetting about since the 4.4 code base is getting old. We don't have this issue in 4.5 or newer. We will always expect to wait in 4.5 or newer, but I overlooked that this was the reason for the first upgrade proceeding without the upgrade checks. > PGs went to unclean state since upgrade of first osd , i.e. osd-1 (as they took >10 mins to come to CLEAN state due to ongoing FIO) @Neha So if the IO is stopped, the PGs come back to a clean state, right? In this case, the IO just sounds like it is causing too heavy of a load for the PGs to recover even during the 10 minute timeout. Can we reduce the amount of IO load during the test? The cluster just sounds underpowered to recover in a reasonable time. I don't see anything Rook can do to improve the test, except changing the upgrade timeout. Since we have the continueUpgradeAfterChecksEvenIfNotHealthy set in OCS, it really doesn't matter if the timeout is 1 minute or 10 minutes, we are going to force the upgrade anyway. I would propose we drop the timeout to 1 minute or even 30 seconds if this flag is set. Perhaps the timeout should be a setting on the CR. @Seb Any concern with lowering the default timeout if the continue flag is set?
Discussed offline with Seb and we agreed that the timeout during upgrade should be configurable in the cluster CR. This will allow OCS to set it to something short such as one minute or even less. This also means we would need an OCS change to apply the shorter timeout.
After digging in more to the implementation, the 10 minute timeout is coming from the ok-to-continue check on the osd: https://github.com/rook/rook/blob/8592caed58170683cbea7abec34bc37097635b83/pkg/daemon/ceph/client/upgrade.go#L221 An upstream Rook issue was opened to describe the issue and fix in more detail: https://github.com/rook/rook/issues/5790 OCS could set a timeout to effectively wait one minute between each OSD upgraded instead of 10 minutes.
Instead of going for the fully configurable fix, let's have a simple fix for 4.5 that reduces the timeout from 10 min to 1 min. https://github.com/openshift/rook/pull/80 The fully configurable change will come in 4.6 with the changes described in issue #5790 mentioned previously. @Petr Ready to ack the BZ with this proposal?
Sounds good to me Travis. Thanks, acking the BZ.
verified on ocs-operator.v4.5.0-54.ci
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory (Red Hat OpenShift Container Storage 4.5.0 bug fix and enhancement update), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2020:3754
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days