periodic-cluster-api-test-release-0-3 #1538351930013650944
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 4m27s |
| Revision | release-0.3 |
... skipping 777 lines ... I0619 02:46:03.954870 8450 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" I0619 02:46:04.776957 8450 kubeadmconfig_controller.go:223] "msg"="Cluster infrastructure is not ready, waiting" "kind"="Machine" "kubeadmconfig"={"Namespace":"default","Name":"my-machine-config"} "name"="my-machine" "version"="109" [32m•[0mI0619 02:46:04.800092 8450 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 1 of 1 Specs in 13.427 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (13.43s) PASS ok sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers 44.857s === RUN TestNewInitControlPlaneAdditionalFileEncodings --- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.03s) === RUN TestNewInitControlPlaneCommands ... skipping 316 lines ... === RUN Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined --- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s) --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s) --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s) === RUN Test_clusterctlClient_GetProviderComponents === RUN Test_clusterctlClient_GetProviderComponents/Pass === RUN Test_clusterctlClient_GetProviderComponents/Fail --- PASS: Test_clusterctlClient_GetProviderComponents (0.00s) --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s) --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s) === RUN Test_getComponentsByName_withEmptyVariables --- PASS: Test_getComponentsByName_withEmptyVariables (0.01s) === RUN Test_clusterctlClient_templateOptionsToVariables === RUN Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options) === RUN Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables) === RUN Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts) ... skipping 1398 lines ... I0619 02:45:51.918438 10479 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1 I0619 02:45:51.918475 10479 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","selector":{},"template":{"metadata":{},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}}}},"status":{}}} I0619 02:45:51.918543 10479 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}} I0619 02:45:51.918576 10479 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" I0619 02:45:51.918616 10479 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I0619 02:45:51.918952 10479 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1 2022/06/19 02:45:52 http: TLS handshake error from 127.0.0.1:35780: EOF === RUN TestClusterReconcilePhases === RUN TestClusterReconcilePhases/reconcile_infrastructure === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref I0619 02:45:52.217134 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test-cluster" "namespace"="test-namespace" "err"="cannot create a metadata client without a rest config" I0619 02:45:52.221199 10479 cluster_controller_phases.go:76] "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test" ... skipping 105 lines ... --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s) === RUN TestReconcileInfrastructure === RUN TestReconcileInfrastructure/new_machine,_infrastructure_config_ready I0619 02:45:52.264453 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" === RUN TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed I0619 02:45:52.266002 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" E0619 02:45:52.266292 10479 machine_controller_phases.go:246] "msg"="Machine infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine \"infra-config1\" for Machine \"machine-test\" in namespace \"default\", requeuing: requeue in 1s" === RUN TestReconcileInfrastructure/infrastructure_ref_is_paused I0619 02:45:52.266667 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" --- PASS: TestReconcileInfrastructure (0.00s) --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.00s) --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s) --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s) === RUN TestWatches I0619 02:45:52.637821 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={} E0619 02:45:52.738478 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I0619 02:45:52.747355 10479 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine" I0619 02:45:52.747461 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}} I0619 02:45:52.856118 10479 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine" I0619 02:45:52.856204 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}} I0619 02:45:52.956705 10479 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" "noderef"="node-1" E0619 02:45:52.966733 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" E0619 02:45:52.966796 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I0619 02:45:52.994085 10479 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" "noderef"="node-1" E0619 02:45:53.011573 10479 machine_controller_phases.go:246] controllers/Machine "msg"="Machine infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine \"infra-config1\" for Machine \"machine-created-8kttn\" in namespace \"test-machine-watches-xjpmb\", requeuing: requeue in 1s" E0619 02:45:53.041115 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine \"infra-config1\" for Machine \"machine-created-8kttn\" in namespace \"test-machine-watches-xjpmb\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-8kttn\" in namespace \"test-machine-watches-xjpmb\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" --- PASS: TestWatches (0.81s) === RUN TestIndexMachineByNodeName === RUN TestIndexMachineByNodeName/when_the_machine_has_no_NodeRef === RUN TestIndexMachineByNodeName/when_the_machine_has_valid_a_NodeRef --- PASS: TestIndexMachineByNodeName (0.00s) --- PASS: TestIndexMachineByNodeName/when_the_machine_has_no_NodeRef (0.00s) ... skipping 2 lines ... === RUN TestMachine_Reconcile/reconcile_create I0619 02:45:53.280439 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-vgrl7" "namespace"="test-machine-watches-xjpmb" "count"=1 I0619 02:45:53.280502 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-vgrl7" "namespace"="test-machine-watches-xjpmb" "descendants"="Worker machines: machine-created-8kttn" "indirect descendants count"=0 I0619 02:45:53.294040 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-vgrl7" "namespace"="test-machine-watches-xjpmb" "count"=1 I0619 02:45:53.294163 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-vgrl7" "namespace"="test-machine-watches-xjpmb" "descendants"="Worker machines: machine-created-8kttn" "indirect descendants count"=0 I0619 02:45:54.041677 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-vgrl7" "machine"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"7b27cd1f-b1c2-4fbe-9a56-61bbee879dcc","apiVersion":"v1"} E0619 02:45:54.120817 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-8kttn\" not found" "controller"="machine" "name"="machine-created-8kttn" "namespace"="test-machine-watches-xjpmb" E0619 02:45:55.164897 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-d5prl\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-gm578\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-gm578: secrets \"machine-reconcile-gm578-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-d5prl" "namespace"="default" I0619 02:45:56.165450 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-gm578" "machine"="machine-created-d5prl" "namespace"="default" "cause"="noderef is nil" "node"=null I0619 02:45:56.211404 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-gm578" "machine"="machine-created-d5prl" "namespace"="default" "cause"="noderef is nil" "node"=null I0619 02:45:56.234212 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-gm578" "machine"="machine-created-d5prl" "namespace"="default" "cause"="noderef is nil" "node"=null E0619 02:45:56.265124 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-d5prl\" not found" "controller"="machine" "name"="machine-created-d5prl" "namespace"="default" --- PASS: TestMachine_Reconcile (3.20s) --- PASS: TestMachine_Reconcile/reconcile_create (3.20s) === RUN TestMachineFinalizer === RUN TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one === RUN TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer --- PASS: TestMachineFinalizer (0.00s) ... skipping 13 lines ... --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.00s) --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s) --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.00s) === RUN TestReconcileRequest === RUN TestReconcileRequest/machine_should_be_created I0619 02:45:56.289156 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="created" "namespace"="default" "err"="cannot create a metadata client without a rest config" E0619 02:45:56.300848 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-gm578\" not found" "controller"="cluster" "name"="machine-reconcile-gm578" "namespace"="default" === RUN TestReconcileRequest/machine_should_be_updated I0619 02:45:56.303185 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="updated" "namespace"="default" "err"="cannot create a metadata client without a rest config" === RUN TestReconcileRequest/machine_should_be_deleted I0619 02:45:56.307033 10479 machine_controller.go:305] "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="deleted" "namespace"="default" "cause"="noderef is nil" "node"=null --- PASS: TestReconcileRequest (0.03s) --- PASS: TestReconcileRequest/machine_should_be_created (0.02s) ... skipping 111 lines ... --- PASS: TestMachineDeploymentSyncStatus/scaling_down (0.00s) --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s) === RUN TestMachineHealthCheck_Reconcile === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist I0619 02:45:56.432819 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h6cq9" "namespace"="test-mhc-ztf4j" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value E0619 02:45:56.453454 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-kk4cm\" not found" "cluster"="test-mhc-ztf4j/test-cluster-kk4cm" I0619 02:45:56.453651 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} E0619 02:45:56.561397 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-h6cq9\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-h6cq9\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-h6cq9" "namespace"="test-mhc-ztf4j" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist I0619 02:45:57.561698 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h6cq9" "namespace"="test-mhc-ztf4j" I0619 02:45:57.561815 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-k72g6" "namespace"="test-mhc-78lmm" I0619 02:45:57.561853 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7pxtv" "namespace"="test-mhc-psxkr" I0619 02:45:57.561887 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sxwgn" "namespace"="test-mhc-74wtn" I0619 02:45:57.595905 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:45:57.714279 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sxwgn" "namespace"="test-mhc-74wtn" I0619 02:45:57.714983 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sxwgn" "namespace"="test-mhc-74wtn" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones I0619 02:45:57.753497 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sxwgn" "namespace"="test-mhc-74wtn" E0619 02:45:57.768868 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-74wtn/test-cluster-qzx2x" E0619 02:45:57.770624 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-qzx2x\" not found" "controller"="cluster" "name"="test-cluster-qzx2x" "namespace"="test-mhc-74wtn" I0619 02:45:57.777320 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-752f6" "namespace"="test-mhc-wtfb8" I0619 02:45:57.791801 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:45:57.819413 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-752f6" "namespace"="test-mhc-wtfb8" E0619 02:45:57.882990 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-wtfb8/test-cluster-sggqd" I0619 02:45:57.886726 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-752f6" "namespace"="test-mhc-wtfb8" === RUN TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy I0619 02:45:58.004897 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" inframachine created: test-mhc-machine-infra-56vx8 machine created: test-mhc-machine-9mtwb I0619 02:45:58.050858 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:45:58.051261 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.091746 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.092157 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.100042 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.100427 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.101605 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.101892 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.114766 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.115323 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" node created: test-mhc-node-p724g E0619 02:45:58.150237 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-p724g" E0619 02:45:58.150250 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p724g, got []" "node"="test-mhc-node-p724g" I0619 02:45:58.164961 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.165304 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.173293 10479 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-9mtwb" "namespace"="test-mhc-7dn55" "noderef"="test-mhc-node-p724g" E0619 02:45:58.186629 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p724g, got []" "node"="test-mhc-node-p724g" E0619 02:45:58.186686 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p724g, got []" "node"="test-mhc-node-p724g" E0619 02:45:58.188309 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-p724g" E0619 02:45:58.188361 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-p724g" I0619 02:45:58.208076 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" inframachine created: test-mhc-machine-infra-74zff machine created: test-mhc-machine-wrptn I0619 02:45:58.256827 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.282002 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.291131 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" ... skipping 51 lines ... I0619 02:45:58.425226 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.427864 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.428962 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.429958 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.432046 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.433358 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.433659 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-wrptn/" E0619 02:45:58.451636 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jc9j5, got []" "node"="test-mhc-node-jc9j5" E0619 02:45:58.451948 10479 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-jc9j5" node created: test-mhc-node-jc9j5 I0619 02:45:58.452611 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.453222 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-wrptn/" I0619 02:45:58.465865 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.466363 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-wrptn/" I0619 02:45:58.469199 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.488333 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" Cleaning up nodes, machines and infra machines. I0619 02:45:58.492952 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.493456 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.511233 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:58.511994 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-9mtwb/" I0619 02:45:58.512662 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-7dn55/test-mhc-fgqnq/test-mhc-machine-wrptn/" I0619 02:45:58.533069 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hdx8h" "machine"="test-mhc-machine-9mtwb" "namespace"="test-mhc-7dn55" "cause"="no control plane members" "node"={"kind":"Node","name":"test-mhc-node-p724g","uid":"0a9b0a6a-3908-459e-b8b5-49d959ef3b98","apiVersion":"v1"} E0619 02:45:58.537561 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-7dn55/test-cluster-hdx8h" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine inframachine created: test-mhc-machine-infra-6mfht E0619 02:45:58.593546 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9mtwb\" not found" "controller"="machine" "name"="test-mhc-machine-9mtwb" "namespace"="test-mhc-7dn55" machine created: test-mhc-machine-gfk2f E0619 02:45:58.657867 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-fgqnq\" not found" "controller"="machinehealthcheck" "name"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" E0619 02:45:58.787732 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-machine-watches-xjpmb/machine-reconcile-vgrl7" E0619 02:45:59.593924 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:45:59.658218 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:45:59.682041 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:45:59.738376 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fgqnq" "namespace"="test-mhc-7dn55" I0619 02:45:59.738448 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:45:59.739841 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:45:59.741621 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" ... skipping 398 lines ... I0619 02:46:00.602741 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.604501 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.605349 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.607041 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.609029 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.609714 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.610023 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfk2f/" E0619 02:46:00.610060 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:00.620204 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.620520 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfk2f/" node created: test-mhc-node-xq4vj E0619 02:46:00.710228 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xq4vj, got []" "node"="test-mhc-node-xq4vj" I0619 02:46:00.715617 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" inframachine created: test-mhc-machine-infra-lvrbl I0619 02:46:00.756345 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" machine created: test-mhc-machine-672d6 I0619 02:46:00.763420 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:00.771476 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" ... skipping 314 lines ... I0619 02:46:01.655503 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.658133 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.659321 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.660485 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.661470 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.677848 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" E0619 02:46:01.678704 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:01.679382 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.682273 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.683807 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.685169 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.686970 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:01.690148 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" ... skipping 362 lines ... I0619 02:46:02.684556 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.686358 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.687411 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.689486 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.691674 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.693842 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.694182 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-672d6/" I0619 02:46:02.712290 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.712741 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-672d6/" I0619 02:46:02.714409 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.714806 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-672d6/" E0619 02:46:02.714953 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" E0619 02:46:02.789584 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gdgkn, got []" "node"="test-mhc-node-gdgkn" node created: test-mhc-node-gdgkn I0619 02:46:02.797859 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" inframachine created: test-mhc-machine-infra-szgng machine created: test-mhc-machine-gfksv I0619 02:46:02.816862 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:02.823312 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" ... skipping 331 lines ... I0619 02:46:03.826529 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.829735 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.831348 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.833893 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.848927 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.852268 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" E0619 02:46:03.856159 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:03.856427 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.859636 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.862514 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.865262 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.868018 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:03.870759 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" ... skipping 289 lines ... I0619 02:46:04.862038 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.871043 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.872754 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.874300 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.875722 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.877207 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.877659 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" I0619 02:46:04.898310 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.898845 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" E0619 02:46:04.902773 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:04.903061 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.903663 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" node created: test-mhc-node-xbcjq E0619 02:46:04.931291 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xbcjq, got []" "node"="test-mhc-node-xbcjq" Cleaning up nodes, machines and infra machines. I0619 02:46:04.941079 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.941617 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/test-mhc-node-xbcjq" I0619 02:46:04.966173 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.966719 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" Cleaning up nodes, machines and infra machines. I0619 02:46:04.976849 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.977409 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" I0619 02:46:04.979878 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:04.980397 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfk2f/" I0619 02:46:04.996975 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" I0619 02:46:05.003226 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:05.003847 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfk2f/" I0619 02:46:05.004316 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-672d6/" I0619 02:46:05.017166 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" I0619 02:46:05.021601 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-wzqzg" "namespace"="test-mhc-jd2qd" "count"=2 I0619 02:46:05.021683 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-wzqzg" "namespace"="test-mhc-jd2qd" "descendants"="Worker machines: test-mhc-machine-gfk2f,test-mhc-machine-672d6,test-mhc-machine-gfksv" "indirect descendants count"=1 I0619 02:46:05.026581 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-wzqzg" "namespace"="test-mhc-jd2qd" "count"=2 I0619 02:46:05.026643 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-wzqzg" "namespace"="test-mhc-jd2qd" "descendants"="Worker machines: test-mhc-machine-gfksv,test-mhc-machine-gfk2f,test-mhc-machine-672d6" "indirect descendants count"=1 I0619 02:46:05.027686 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:05.028315 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfk2f/" I0619 02:46:05.028735 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-672d6/" I0619 02:46:05.029179 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-jd2qd/test-mhc-7cjtw/test-mhc-machine-gfksv/" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy E0619 02:46:05.033175 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-7cjtw\" not found" "controller"="machinehealthcheck" "name"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" inframachine created: test-mhc-machine-infra-mbpww machine created: test-mhc-machine-dksld I0619 02:46:05.903275 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-wzqzg" "machine"="test-mhc-machine-gfksv" "namespace"="test-mhc-jd2qd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xbcjq"} E0619 02:46:05.957562 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gfksv\" not found" "controller"="machine" "name"="test-mhc-machine-gfksv" "namespace"="test-mhc-jd2qd" I0619 02:46:06.033440 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7cjtw" "namespace"="test-mhc-jd2qd" I0619 02:46:06.033553 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.049638 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:46:06.080316 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.086403 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.096538 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.137458 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.218569 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.379619 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.700776 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:06.958113 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-wzqzg" "machine"="test-mhc-machine-672d6" "namespace"="test-mhc-jd2qd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-gdgkn"} E0619 02:46:07.008332 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-672d6\" not found" "controller"="machine" "name"="test-mhc-machine-672d6" "namespace"="test-mhc-jd2qd" I0619 02:46:07.341921 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:08.008903 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-wzqzg" "machine"="test-mhc-machine-gfk2f" "namespace"="test-mhc-jd2qd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xq4vj"} E0619 02:46:08.061947 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gfk2f\" not found" "controller"="machine" "name"="test-mhc-machine-gfk2f" "namespace"="test-mhc-jd2qd" I0619 02:46:08.623069 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" E0619 02:46:09.080118 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:09.080362 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" E0619 02:46:09.091573 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-shbqz, got []" "node"="test-mhc-node-shbqz" node created: test-mhc-node-shbqz E0619 02:46:09.091819 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-shbqz, got []" "node"="test-mhc-node-shbqz" inframachine created: test-mhc-machine-infra-j5b8x I0619 02:46:09.117827 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" machine created: test-mhc-machine-q6vbh I0619 02:46:09.133778 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.145604 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.150773 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.171983 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.213219 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.294563 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.455978 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:09.777416 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" E0619 02:46:10.039153 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-jd2qd/test-cluster-wzqzg" I0619 02:46:10.100934 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:10.109452 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:10.132378 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:10.139650 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:10.164083 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" E0619 02:46:10.173118 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:10.175272 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:10.200780 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" node created: test-mhc-node-6ct5v E0619 02:46:10.241533 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6ct5v, got []" "node"="test-mhc-node-6ct5v" I0619 02:46:10.252574 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" inframachine created: test-mhc-machine-infra-f6trz I0619 02:46:10.265783 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" machine created: test-mhc-machine-f8r8m I0619 02:46:10.290141 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:10.418804 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.191038 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.209166 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.216099 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.232963 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.242676 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.253173 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" E0619 02:46:11.257262 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:11.257634 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" E0619 02:46:11.285258 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q55b8, got []" "node"="test-mhc-node-q55b8" node created: test-mhc-node-q55b8 I0619 02:46:11.344874 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" Cleaning up nodes, machines and infra machines. I0619 02:46:11.371958 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.397340 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" Cleaning up nodes, machines and infra machines. I0619 02:46:11.431384 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:11.438579 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-7ft2w" "namespace"="test-mhc-wgn8v" "count"=2 I0619 02:46:11.438673 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-7ft2w" "namespace"="test-mhc-wgn8v" "descendants"="Worker machines: test-mhc-machine-dksld,test-mhc-machine-q6vbh,test-mhc-machine-f8r8m" "indirect descendants count"=1 I0619 02:46:11.444165 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-7ft2w" "namespace"="test-mhc-wgn8v" "count"=2 I0619 02:46:11.444231 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-7ft2w" "namespace"="test-mhc-wgn8v" "descendants"="Worker machines: test-mhc-machine-dksld,test-mhc-machine-q6vbh,test-mhc-machine-f8r8m" "indirect descendants count"=1 === RUN TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout E0619 02:46:11.472982 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-6cgns\" not found" "controller"="machinehealthcheck" "name"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" inframachine created: test-mhc-machine-infra-qdqmf machine created: test-mhc-machine-5cb2z I0619 02:46:12.257820 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-7ft2w" "machine"="test-mhc-machine-dksld" "namespace"="test-mhc-wgn8v" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-shbqz"} E0619 02:46:12.326325 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-dksld\" not found" "controller"="machine" "name"="test-mhc-machine-dksld" "namespace"="test-mhc-wgn8v" I0619 02:46:12.473303 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6cgns" "namespace"="test-mhc-wgn8v" I0619 02:46:12.473423 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:12.508394 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:46:12.636305 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:13.326898 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-7ft2w" "machine"="test-mhc-machine-q6vbh" "namespace"="test-mhc-wgn8v" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6ct5v"} E0619 02:46:13.364115 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-q6vbh\" not found" "controller"="machine" "name"="test-mhc-machine-q6vbh" "namespace"="test-mhc-wgn8v" I0619 02:46:14.364655 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-7ft2w" "machine"="test-mhc-machine-f8r8m" "namespace"="test-mhc-wgn8v" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-q55b8"} E0619 02:46:14.427066 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-f8r8m\" not found" "controller"="machine" "name"="test-mhc-machine-f8r8m" "namespace"="test-mhc-wgn8v" I0619 02:46:15.436871 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" E0619 02:46:15.441589 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:15.442187 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" node created: test-mhc-node-2rnzv E0619 02:46:15.525812 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2rnzv, got []" "node"="test-mhc-node-2rnzv" E0619 02:46:15.525812 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2rnzv, got []" "node"="test-mhc-node-2rnzv" I0619 02:46:15.533638 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" inframachine created: test-mhc-machine-infra-57l48 machine created: test-mhc-machine-pc6b8 I0619 02:46:15.550243 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:15.565352 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.458449 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" E0619 02:46:16.458637 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-wgn8v/test-cluster-7ft2w" I0619 02:46:16.459425 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.469534 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.483430 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.488706 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.512842 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.520967 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.533956 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.548268 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" E0619 02:46:16.557899 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-zl9fc, got []" "node"="test-mhc-node-zl9fc" node created: test-mhc-node-zl9fc I0619 02:46:16.562503 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.568834 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" inframachine created: test-mhc-machine-infra-h9s8z machine created: test-mhc-machine-tq2d7 I0619 02:46:16.617929 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" ... skipping 6 lines ... Cleaning up nodes, machines and infra machines. I0619 02:46:16.719830 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.724136 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" Cleaning up nodes, machines and infra machines. I0619 02:46:16.738043 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.744839 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.745434 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-lclxx/test-mhc-fdlwh/test-mhc-machine-5cb2z/" I0619 02:46:16.777239 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:16.777841 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-lclxx/test-mhc-fdlwh/test-mhc-machine-5cb2z/" I0619 02:46:16.778262 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-lclxx/test-mhc-fdlwh/test-mhc-machine-pc6b8/" I0619 02:46:16.804218 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-2hg6v" "namespace"="test-mhc-lclxx" "count"=3 I0619 02:46:16.804305 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2hg6v" "namespace"="test-mhc-lclxx" "descendants"="Worker machines: test-mhc-machine-tq2d7,test-mhc-machine-5cb2z,test-mhc-machine-pc6b8" "indirect descendants count"=0 I0619 02:46:16.809717 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-2hg6v" "namespace"="test-mhc-lclxx" "count"=3 I0619 02:46:16.809781 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2hg6v" "namespace"="test-mhc-lclxx" "descendants"="Worker machines: test-mhc-machine-5cb2z,test-mhc-machine-pc6b8,test-mhc-machine-tq2d7" "indirect descendants count"=0 === RUN TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_longer_than_the_NodeStartupTimeout === RUN TestMachineHealthCheck_Reconcile/when_a_Machine's_Node_has_gone_away === RUN TestMachineHealthCheck_Reconcile/should_react_when_a_Node_transitions_to_unhealthy E0619 02:46:16.912086 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-fdlwh\" not found" "controller"="machinehealthcheck" "name"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" inframachine created: test-mhc-machine-infra-r78pb machine created: test-mhc-machine-tsppb E0619 02:46:16.956598 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-pc6b8\" in namespace \"test-mhc-lclxx\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-pc6b8" "namespace"="test-mhc-lclxx" I0619 02:46:17.912361 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdlwh" "namespace"="test-mhc-lclxx" I0619 02:46:17.912467 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:17.927218 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:46:17.945605 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:17.946728 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:17.948546 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" ... skipping 24 lines ... I0619 02:46:18.007996 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.010147 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.011953 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.013996 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.016463 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.018384 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" E0619 02:46:18.018904 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tq2d7\" not found" "controller"="machine" "name"="test-mhc-machine-tq2d7" "namespace"="test-mhc-lclxx" I0619 02:46:18.020472 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.022291 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.024139 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.025885 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.027649 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:18.029804 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" ... skipping 461 lines ... I0619 02:46:19.046134 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.055485 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.057537 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.059367 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.064750 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.069689 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" E0619 02:46:19.071100 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5cb2z\" not found" "controller"="machine" "name"="test-mhc-machine-5cb2z" "namespace"="test-mhc-lclxx" I0619 02:46:19.076416 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.079345 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.081660 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.085114 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.088140 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:19.090063 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" ... skipping 453 lines ... I0619 02:46:20.087202 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.087820 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.088926 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.090614 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.092316 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-2hg6v" "machine"="test-mhc-machine-pc6b8" "namespace"="test-mhc-lclxx" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-zl9fc"} I0619 02:46:20.092586 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.092836 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-t7lx7/test-mhc-2cwgl/test-mhc-machine-tsppb/" I0619 02:46:20.108027 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.108326 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-t7lx7/test-mhc-2cwgl/test-mhc-machine-tsppb/" E0619 02:46:20.137969 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-pc6b8\" not found" "controller"="machine" "name"="test-mhc-machine-pc6b8" "namespace"="test-mhc-lclxx" E0619 02:46:20.170197 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hz9hx, got []" "node"="test-mhc-node-hz9hx" E0619 02:46:20.170883 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hz9hx, got []" "node"="test-mhc-node-hz9hx" node created: test-mhc-node-hz9hx I0619 02:46:20.194495 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.208235 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.213632 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.217911 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.218951 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.219194 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-t7lx7/test-mhc-2cwgl/test-mhc-machine-tsppb/test-mhc-node-hz9hx" I0619 02:46:20.238198 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.238617 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-t7lx7/test-mhc-2cwgl/test-mhc-machine-tsppb/test-mhc-node-hz9hx" Cleaning up nodes, machines and infra machines. I0619 02:46:20.251874 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.252202 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-t7lx7/test-mhc-2cwgl/test-mhc-machine-tsppb/" I0619 02:46:20.266521 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2xbct" "namespace"="test-mhc-t7lx7" "descendants"="Worker machines: test-mhc-machine-tsppb" "indirect descendants count"=1 I0619 02:46:20.271228 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2xbct" "namespace"="test-mhc-t7lx7" "descendants"="Worker machines: test-mhc-machine-tsppb" "indirect descendants count"=1 === RUN TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted I0619 02:46:20.398246 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2cwgl" "namespace"="test-mhc-t7lx7" I0619 02:46:20.404068 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" "creating"=1 "need"=1 I0619 02:46:20.404117 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:20.415351 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-895zc-qf2gn\"" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:20.501531 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:20.528506 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:46:20.551697 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:20.552515 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" E0619 02:46:21.138435 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:21.551895 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" E0619 02:46:21.833502 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-lclxx/test-cluster-2hg6v" I0619 02:46:22.139066 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-2xbct" "machine"="test-mhc-machine-tsppb" "namespace"="test-mhc-t7lx7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hz9hx"} E0619 02:46:22.187885 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tsppb\" not found" "controller"="machine" "name"="test-mhc-machine-tsppb" "namespace"="test-mhc-t7lx7" I0619 02:46:22.552965 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:23.197477 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:23.197554 10479 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:23.205717 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:23.206515 10479 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:23.217700 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" ... skipping 7 lines ... I0619 02:46:23.255887 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:23.255948 10479 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:23.554051 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:24.242478 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:24.242546 10479 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:25.000725 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:25.001221 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1s" "reason"="NodeStartupTimeout" "target"="test-mhc-gk4gl/test-mhc-ggh4w/mhc-ms-895zc-qf2gn/" I0619 02:46:25.009590 10479 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:25.015589 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:25.016035 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1s" "reason"="NodeStartupTimeout" "target"="test-mhc-gk4gl/test-mhc-ggh4w/mhc-ms-895zc-qf2gn/" I0619 02:46:25.017631 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:25.017671 10479 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:25.025275 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:25.025672 10479 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="Node failed to report startup in 1s" "reason"="NodeStartupTimeout" "target"="test-mhc-gk4gl/test-mhc-ggh4w/mhc-ms-895zc-qf2gn/" I0619 02:46:25.026627 10479 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:25.044855 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:25.044909 10479 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:25.067442 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-rhd4k" "namespace"="test-mhc-gk4gl" "count"=1 I0619 02:46:25.068196 10479 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-rhd4k" "namespace"="test-mhc-gk4gl" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-895zc" I0619 02:46:25.068983 10479 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" "machine"="mhc-ms-895zc-qf2gn" I0619 02:46:25.074658 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ggh4w" "namespace"="test-mhc-gk4gl" I0619 02:46:25.074949 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-rhd4k" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" "cause"="cluster is being deleted" "node"=null I0619 02:46:25.084802 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-rhd4k" "namespace"="test-mhc-gk4gl" "descendants"="Machine sets: mhc-ms-895zc;Worker machines: mhc-ms-895zc-qf2gn" "indirect descendants count"=1 I0619 02:46:25.087304 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" "creating"=1 "need"=1 I0619 02:46:25.087350 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" === RUN TestMachineHealthCheck_Reconcile/when_a_machine_is_paused === RUN TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created E0619 02:46:25.090964 10479 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to sync machines: failed to clone infrastructure configuration for MachineSet \"mhc-ms-895zc\" in namespace \"test-mhc-gk4gl\": failed to retrieve InfrastructureMachineTemplate external object \"test-mhc-gk4gl\"/\"mhc-ms-template-7fx74\": infrastructuremachinetemplates.infrastructure.cluster.x-k8s.io \"mhc-ms-template-7fx74\" not found. failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-895zc\" not found" "machineset"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" E0619 02:46:25.091036 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to sync machines: failed to clone infrastructure configuration for MachineSet \"mhc-ms-895zc\" in namespace \"test-mhc-gk4gl\": failed to retrieve InfrastructureMachineTemplate external object \"test-mhc-gk4gl\"/\"mhc-ms-template-7fx74\": infrastructuremachinetemplates.infrastructure.cluster.x-k8s.io \"mhc-ms-template-7fx74\" not found. failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-895zc\" not found" "controller"="machineset" "name"="mhc-ms-895zc" "namespace"="test-mhc-gk4gl" I0619 02:46:25.091458 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-rhd4k" "namespace"="test-mhc-gk4gl" "descendants"="Worker machines: mhc-ms-895zc-qf2gn" "indirect descendants count"=1 I0619 02:46:25.261475 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-rhd4k" "machine"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" "cause"="cluster is being deleted" "node"=null E0619 02:46:25.309768 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-t7lx7/test-cluster-2xbct" E0619 02:46:25.310593 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-895zc-qf2gn\" not found" "controller"="machine" "name"="mhc-ms-895zc-qf2gn" "namespace"="test-mhc-gk4gl" I0619 02:46:25.329446 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" inframachine created: test-mhc-machine-infra-9x26s machine created: test-mhc-machine-xp5xx I0619 02:46:25.346214 10479 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0619 02:46:25.473571 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:25.474601 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" ... skipping 348 lines ... I0619 02:46:26.314563 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.316616 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.319349 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.320135 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.321252 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.323567 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" E0619 02:46:26.324064 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" I0619 02:46:26.324372 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" E0619 02:46:26.354668 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t4gdx, got []" "node"="test-mhc-node-t4gdx" node created: test-mhc-node-t4gdx E0619 02:46:26.354966 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t4gdx, got []" "node"="test-mhc-node-t4gdx" I0619 02:46:26.397818 10479 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "remediation request name"="test-mhc-machine-xp5xx" "target"="test-mhc-85kpk/test-mhc-9b42q/test-mhc-machine-xp5xx/" I0619 02:46:26.413020 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.435569 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.438049 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.443547 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.446873 10479 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request" "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "remediation request name"="test-mhc-machine-xp5xx" "target"="test-mhc-85kpk/test-mhc-9b42q/test-mhc-machine-xp5xx/test-mhc-node-t4gdx" I0619 02:46:26.463860 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" Cleaning up nodes, machines and infra machines. I0619 02:46:26.479334 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.483493 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.487558 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9b42q" "namespace"="test-mhc-85kpk" I0619 02:46:26.495215 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-mxnjq" "namespace"="test-mhc-85kpk" "descendants"="Worker machines: test-mhc-machine-xp5xx" "indirect descendants count"=1 ... skipping 357 lines ... I0619 02:46:27.375201 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.376922 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.378643 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.380397 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.382335 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.384182 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" E0619 02:46:27.384224 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-xp5xx\" not found" "controller"="machine" "name"="test-mhc-machine-xp5xx" "namespace"="test-mhc-85kpk" I0619 02:46:27.386011 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.387812 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.389611 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.391365 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.393105 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:27.394887 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" ... skipping 466 lines ... I0619 02:46:28.387403 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.389129 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.391000 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.391838 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.394079 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.396490 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.401924 10479 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request" "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "remediation request name"="test-mhc-machine-mgmnw" "target"="test-mhc-sct7x/test-mhc-m6k4q/test-mhc-machine-mgmnw/" I0619 02:46:28.421613 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" E0619 02:46:28.461477 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-m4m2x, got []" "node"="test-mhc-node-m4m2x" node created: test-mhc-node-m4m2x E0619 02:46:28.462224 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-m4m2x, got []" "node"="test-mhc-node-m4m2x" E0619 02:46:28.462385 10479 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-m4m2x, got []" "node"="test-mhc-node-m4m2x" I0619 02:46:28.469138 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.491923 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.502820 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.508084 10479 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request" "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "remediation request name"="test-mhc-machine-mgmnw" "target"="test-mhc-sct7x/test-mhc-m6k4q/test-mhc-machine-mgmnw/test-mhc-node-m4m2x" I0619 02:46:28.534878 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.548071 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.568782 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" Cleaning up nodes, machines and infra machines. I0619 02:46:28.590072 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.594274 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" I0619 02:46:28.603661 10479 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request" "message"="" "reason"="NodeNotFound" "remediation request name"="test-mhc-machine-mgmnw" "target"="test-mhc-sct7x/test-mhc-m6k4q/test-mhc-machine-mgmnw/" I0619 02:46:28.611744 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hhqt9" "namespace"="test-mhc-sct7x" "descendants"="Worker machines: test-mhc-machine-mgmnw" "indirect descendants count"=1 I0619 02:46:28.616934 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hhqt9" "namespace"="test-mhc-sct7x" "descendants"="Worker machines: test-mhc-machine-mgmnw" "indirect descendants count"=1 --- PASS: TestMachineHealthCheck_Reconcile (32.21s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.04s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.13s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.14s) ... skipping 12 lines ... --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s) machinehealthcheck_controller_test.go:933: skipping until made stable --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (1.42s) --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.11s) === RUN TestClusterToMachineHealthCheck === RUN TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster E0619 02:46:28.622978 10479 machinehealthcheck_controller.go:416] "msg"="expected a Cluster" "error"="incorrect type" "type"="handler.MapObject" === RUN TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Cluster_in_the_same_namespace === RUN TestClusterToMachineHealthCheck/when_2_MachineHealthChecks_exists_for_the_Cluster_in_the_same_namespace === RUN TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_the_same_namespace === RUN TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_another_namespace --- PASS: TestClusterToMachineHealthCheck (0.00s) --- PASS: TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster (0.00s) --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Cluster_in_the_same_namespace (0.00s) --- PASS: TestClusterToMachineHealthCheck/when_2_MachineHealthChecks_exists_for_the_Cluster_in_the_same_namespace (0.00s) --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_the_same_namespace (0.00s) --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_another_namespace (0.00s) === RUN TestMachineToMachineHealthCheck === RUN TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine E0619 02:46:28.624976 10479 machinehealthcheck_controller.go:445] "msg"="expected a Machine" "error"="incorrect type" "type"="handler.MapObject" === RUN TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace === RUN TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace === RUN TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace === RUN TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace --- PASS: TestMachineToMachineHealthCheck (0.00s) --- PASS: TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine (0.00s) --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace (0.00s) --- PASS: TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace (0.00s) --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace (0.00s) --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace (0.00s) === RUN TestNodeToMachineHealthCheck === RUN TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node E0619 02:46:28.626862 10479 machinehealthcheck_controller.go:474] "msg"="expected a Node" "error"="incorrect type" "type"="handler.MapObject" === RUN TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node E0619 02:46:28.627119 10479 machinehealthcheck_controller.go:480] "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node node1, got []" "node"="node1" === RUN TestNodeToMachineHealthCheck/when_two_Machines_exist_for_the_Node E0619 02:46:28.627678 10479 machinehealthcheck_controller.go:480] "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node node1, got [machine1 machine2]" "node"="node1" === RUN TestNodeToMachineHealthCheck/when_no_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace === RUN TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace === RUN TestNodeToMachineHealthCheck/when_two_MachineHealthChecks_exist_for_the_Node_in_the_Machine's_namespace === RUN TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node,_but_not_in_the_Machine's_cluster E0619 02:46:28.631276 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-m6k4q\" not found" "controller"="machinehealthcheck" "name"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" --- PASS: TestNodeToMachineHealthCheck (0.01s) --- PASS: TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node (0.00s) --- PASS: TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node (0.00s) --- PASS: TestNodeToMachineHealthCheck/when_two_Machines_exist_for_the_Node (0.00s) --- PASS: TestNodeToMachineHealthCheck/when_no_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace (0.00s) --- PASS: TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace (0.00s) ... skipping 27 lines ... --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_nil (0.00s) --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_not_an_int_or_percentage (0.00s) --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_an_int (0.00s) --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_40%_(of_5) (0.00s) --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_60%_(of_7) (0.00s) === RUN TestPatchTargets I0619 02:46:28.632717 10479 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine1/" I0619 02:46:28.633376 10479 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine2/" E0619 02:46:28.635175 10479 machinehealthcheck_controller.go:320] "msg"="failed to patch healthy machine status for machine" "error"="machines.cluster.x-k8s.io \"machine1\" not found" "machine"="machine1" --- PASS: TestPatchTargets (0.00s) === RUN TestGetTargetsFromMHC === RUN TestGetTargetsFromMHC/with_no_matching_machines === RUN TestGetTargetsFromMHC/when_a_machine's_node_is_missing === RUN TestGetTargetsFromMHC/when_a_machine's_labels_do_not_match_the_selector === RUN TestGetTargetsFromMHC/with_multiple_machines,_should_match_correct_nodes ... skipping 26 lines ... --- PASS: TestMachineSetOwnerReference (0.00s) --- PASS: TestMachineSetOwnerReference/should_add_cluster_owner_reference_to_machine_set (0.00s) --- PASS: TestMachineSetOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_deployment (0.00s) === RUN TestMachineSetReconcile === RUN TestMachineSetReconcile/ignore_machine_sets_marked_for_deletion === RUN TestMachineSetReconcile/records_event_if_reconcile_fails E0619 02:46:28.646810 10479 machineset_controller.go:151] "msg"="Failed to reconcile MachineSet" "error"="failed to calculate MachineSet's Status: failed to calculate status for MachineSet default/machineset1: invalid label key \"--$-invalid\": name part must consist of alphanumeric characters, '-', '_' or '.', and must start and end with an alphanumeric character (e.g. 'MyName', or 'my.name', or '123-abc', regex used for validation is '([A-Za-z0-9][-A-Za-z0-9_.]*)?[A-Za-z0-9]')" "machineset"="machineset1" "namespace"="default" --- PASS: TestMachineSetReconcile (0.00s) --- PASS: TestMachineSetReconcile/ignore_machine_sets_marked_for_deletion (0.00s) --- PASS: TestMachineSetReconcile/records_event_if_reconcile_fails (0.00s) === RUN TestMachineSetToMachines === RUN TestMachineSetToMachines/should_return_empty_request_when_controller_is_set === RUN TestMachineSetToMachines/should_return_nil_if_machine_has_no_owner_reference ... skipping 8 lines ... --- PASS: TestAdoptOrphan (0.00s) === RUN TestHasMatchingLabels === RUN TestHasMatchingLabels/machine_set_and_machine_have_matching_labels === RUN TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels === RUN TestHasMatchingLabels/machine_set_has_empty_selector === RUN TestHasMatchingLabels/machine_set_has_bad_selector E0619 02:46:28.648593 10479 machineset_controller.go:569] "msg"="Unable to convert selector" "error"="\"bad-operator\" is not a valid pod selector operator" "machine"="match" "machineset"="" "namespace"="" --- PASS: TestHasMatchingLabels (0.00s) --- PASS: TestHasMatchingLabels/machine_set_and_machine_have_matching_labels (0.00s) --- PASS: TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels (0.00s) --- PASS: TestHasMatchingLabels/machine_set_has_empty_selector (0.00s) --- PASS: TestHasMatchingLabels/machine_set_has_bad_selector (0.00s) === RUN TestMachineToDelete ... skipping 58 lines ... Running Suite: Controllers Suite ================================ Random Seed: [1m1655606740[0m Will run [1m16[0m of [1m16[0m specs [32m•[0mI0619 02:46:28.768799 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hhqt9" "machine"="test-mhc-machine-mgmnw" "namespace"="test-mhc-sct7x" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-m4m2x"} E0619 02:46:28.785991 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-6hsgs\" not found" "controller"="cluster" "name"="test1-6hsgs" "namespace"="default" E0619 02:46:29.016185 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-mgmnw\" not found" "controller"="machine" "name"="test-mhc-machine-mgmnw" "namespace"="test-mhc-sct7x" I0619 02:46:29.631540 10479 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m6k4q" "namespace"="test-mhc-sct7x" [32m•[0mI0619 02:46:29.922163 10479 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-7fbjb" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I0619 02:46:30.046871 10479 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-7fbjb" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E0619 02:46:30.051978 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\"" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" E0619 02:46:31.072993 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" [32m•[0mE0619 02:46:32.115818 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-gk4gl/test-cluster-rhd4k" E0619 02:46:32.145628 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-jwbxq\" not found" "controller"="cluster" "name"="test3-jwbxq" "namespace"="default" E0619 02:46:33.146387 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" E0619 02:46:34.164689 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" E0619 02:46:34.165095 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-85kpk/test-cluster-mxnjq" [32m•[0mE0619 02:46:35.177072 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-sct7x/test-cluster-hhqt9" E0619 02:46:35.181114 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-pv9rd: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-pv9rd" "namespace"="default" E0619 02:46:36.181845 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" E0619 02:46:36.564395 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-hdx8h\" for machine \"test-mhc-machine-wrptn\" in namespace \"test-mhc-7dn55\": Cluster.cluster.x-k8s.io \"test-cluster-hdx8h\" not found" "controller"="machine" "name"="test-mhc-machine-wrptn" "namespace"="test-mhc-7dn55" E0619 02:46:37.191568 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-pv9rd: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-pv9rd" "namespace"="default" [32m•[0mE0619 02:46:38.192372 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" E0619 02:46:39.193150 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-pv9rd: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-pv9rd" "namespace"="default" E0619 02:46:40.203058 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" I0619 02:46:40.341032 10479 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-gw2c7" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E0619 02:46:40.357393 10479 machine_controller_noderef.go:73] controllers/Machine "msg"="Failed to retrieve Node by ProviderID" "error"="the cache is not started, can not read objects" "machine"="test6-gw2c7" "namespace"="default" E0619 02:46:40.376277 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\", the cache is not started, can not read objects]" "controller"="machine" "name"="test6-gw2c7" "namespace"="default" E0619 02:46:41.203938 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-pv9rd: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-pv9rd" "namespace"="default" I0619 02:46:41.398434 10479 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-gw2c7" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I0619 02:46:41.398688 10479 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-gw2c7" "namespace"="default" "noderef"="id-node-1" E0619 02:46:41.414404 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\"" "controller"="machine" "name"="test6-gw2c7" "namespace"="default" E0619 02:46:42.208831 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" [32m•[0mI0619 02:46:42.217970 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0619 02:46:42.218767 10479 machine_controller_phases.go:219] "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" I0619 02:46:42.218808 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0619 02:46:42.219408 10479 machine_controller_phases.go:278] "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" I0619 02:46:42.219437 10479 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" [32m•[0mI0619 02:46:42.219915 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" ... skipping 13 lines ... I0619 02:46:42.230772 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" [32m•[0mI0619 02:46:42.232166 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0619 02:46:42.232798 10479 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0619 02:46:42.233381 10479 machine_controller_phases.go:278] "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" I0619 02:46:42.233413 10479 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" [32m•[0mI0619 02:46:42.233897 10479 machine_controller.go:327] "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" E0619 02:46:42.235101 10479 machine_controller.go:494] "msg"="Error creating a remote client while deleting Machine, won't retry" "error"="failed to create REST configuration for Cluster default/test-cluster: invalid configuration: no configuration has been provided" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" [32m•[0mI0619 02:46:42.278613 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2 I0619 02:46:42.278650 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.288386 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-w6b2x-6657c7fddb-nqb7n\"" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.288527 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.302351 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-w6b2x-6657c7fddb-v5r8x\"" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.374968 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2 I0619 02:46:42.375008 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.383150 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-w6b2x-6657c7fddb-59txh\"" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.383249 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.391953 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-w6b2x-6657c7fddb-kc8qf\"" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.414926 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-lcx96" "machine"="test6-gw2c7" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"d9a1be7a-8477-495e-87c4-adba9b120ff4","apiVersion":"v1"} E0619 02:46:42.432060 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-gw2c7\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-gw2c7" "namespace"="default" I0619 02:46:42.486625 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3 I0619 02:46:42.486678 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.495716 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-w6b2x-6657c7fddb-79dkx\"" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" I0619 02:46:42.592514 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1 I0619 02:46:42.592552 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" I0619 02:46:42.602363 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-w6b2x-cdfc6fd6c-sz2lj\"" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" E0619 02:46:42.811632 10479 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-w6b2x-cdfc6fd6c-sz2lj-hvsbk for machine md-test/md-w6b2x-cdfc6fd6c-sz2lj: the cache is not started, can not read objects" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" I0619 02:46:42.837712 10479 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2 I0619 02:46:42.837748 10479 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0619 02:46:42.844490 10479 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "machine"="md-w6b2x-6657c7fddb-59txh" I0619 02:46:42.861199 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2 I0619 02:46:42.861240 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" I0619 02:46:42.872301 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-w6b2x-cdfc6fd6c-cl44n\"" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" ... skipping 3 lines ... I0619 02:46:43.118269 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3 I0619 02:46:43.118307 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" I0619 02:46:43.127496 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-w6b2x-cdfc6fd6c-7vwt7\"" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" I0619 02:46:43.198600 10479 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0 I0619 02:46:43.198637 10479 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0619 02:46:43.205618 10479 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-w6b2x-6657c7fddb" "namespace"="md-test" "machine"="md-w6b2x-6657c7fddb-79dkx" E0619 02:46:43.209404 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-pv9rd: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-pv9rd" "namespace"="default" I0619 02:46:43.458051 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-lcx96" "machine"="test6-gw2c7" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"d9a1be7a-8477-495e-87c4-adba9b120ff4","apiVersion":"v1"} E0619 02:46:43.458776 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-gw2c7\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-gw2c7" "namespace"="default" I0619 02:46:43.463471 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1 I0619 02:46:43.463590 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-w6b2x-74d45c49c5" "namespace"="md-test" I0619 02:46:43.473729 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-w6b2x-74d45c49c5-rrp9n\"" "machineset"="md-w6b2x-74d45c49c5" "namespace"="md-test" I0619 02:46:43.696732 10479 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2 I0619 02:46:43.696766 10479 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" I0619 02:46:43.700591 10479 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "machine"="md-w6b2x-cdfc6fd6c-cl44n" ... skipping 5 lines ... I0619 02:46:43.932005 10479 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "machine"="md-w6b2x-cdfc6fd6c-7vwt7" I0619 02:46:44.040998 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-w6b2x-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3 I0619 02:46:44.041034 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-w6b2x-74d45c49c5" "namespace"="md-test" I0619 02:46:44.051204 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-w6b2x-74d45c49c5-2vjfp\"" "machineset"="md-w6b2x-74d45c49c5" "namespace"="md-test" I0619 02:46:44.209977 10479 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-lcx96" "namespace"="default" "count"=1 I0619 02:46:44.210051 10479 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-lcx96" "namespace"="default" "descendants"="Control plane machines: test6-gw2c7" "indirect descendants count"=0 E0619 02:46:44.224433 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-7fbjb: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-7fbjb" "namespace"="default" E0619 02:46:44.286180 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-w6b2x\" not found" "controller"="machinedeployment" "name"="md-w6b2x" "namespace"="md-test" I0619 02:46:44.286317 10479 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0 I0619 02:46:44.286355 10479 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" [32m•[0mI0619 02:46:44.290753 10479 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-w6b2x-cdfc6fd6c" "namespace"="md-test" "machine"="md-w6b2x-cdfc6fd6c-sz2lj" I0619 02:46:44.417607 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-klkrd" "namespace"="ms-test" "creating"=2 "need"=2 I0619 02:46:44.417642 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-klkrd" "namespace"="ms-test" I0619 02:46:44.430536 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-klkrd-rdb5p\"" "machineset"="ms-klkrd" "namespace"="ms-test" I0619 02:46:44.430583 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-klkrd" "namespace"="ms-test" I0619 02:46:44.442321 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-klkrd-n544t\"" "machineset"="ms-klkrd" "namespace"="ms-test" I0619 02:46:44.465037 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-w6b2x-6657c7fddb-nqb7n" "namespace"="md-test" I0619 02:46:44.465075 10479 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-w6b2x-6657c7fddb-nqb7n" "namespace"="md-test" I0619 02:46:44.479529 10479 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-w6b2x-6657c7fddb-v5r8x" "namespace"="md-test" I0619 02:46:44.479565 10479 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-w6b2x-6657c7fddb-v5r8x" "namespace"="md-test" I0619 02:46:44.501190 10479 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-lcx96" "machine"="test6-gw2c7" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"d9a1be7a-8477-495e-87c4-adba9b120ff4","apiVersion":"v1"} E0619 02:46:44.501966 10479 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-gw2c7\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-gw2c7" "namespace"="default" I0619 02:46:44.578202 10479 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-klkrd" "namespace"="ms-test" "creating"=1 "need"=2 I0619 02:46:44.578248 10479 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-klkrd" "namespace"="ms-test" I0619 02:46:44.595942 10479 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-klkrd-nrwtm\"" "machineset"="ms-klkrd" "namespace"="ms-test" E0619 02:46:44.720503 10479 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-klkrd-nrwtm-sql7q for machine ms-test/ms-klkrd-nrwtm: the cache is not started, can not read objects" "machineset"="ms-klkrd" "namespace"="ms-test" E0619 02:46:44.946601 10479 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="ms-test/test-cluster" [32m•[0m [1m[32mRan 16 of 16 Specs in 16.299 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m16 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (16.30s) PASS Tearing down test suite I0619 02:46:44.949584 10479 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" I0619 02:46:44.949628 10479 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" I0619 02:46:44.949592 10479 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" I0619 02:46:44.949650 10479 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" I0619 02:46:44.949657 10479 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" I0619 02:46:44.949660 10479 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0619 02:46:44.949664 10479 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" E0619 02:46:44.986568 10479 reflector.go:309] pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: Failed to watch *v1.Node: Get http://127.0.0.1:36337/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1273&timeout=10s&timeoutSeconds=519&watch=true: dial tcp 127.0.0.1:36337: connect: connection refused E0619 02:46:44.986623 10479 reflector.go:309] pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: Failed to watch *v1.Node: Get http://127.0.0.1:36337/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1273&timeout=10s&timeoutSeconds=540&watch=true: dial tcp 127.0.0.1:36337: connect: connection refused ok sigs.k8s.io/cluster-api/controllers 64.676s === RUN TestGetResourceFound --- PASS: TestGetResourceFound (0.00s) === RUN TestGetResourceNotFound --- PASS: TestGetResourceNotFound (0.00s) === RUN TestCloneTemplateResourceNotFound ... skipping 256 lines ... I0619 02:45:54.063630 10863 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook" "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset" I0619 02:45:54.063645 10863 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset" I0619 02:45:54.063852 10863 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server" I0619 02:45:54.064736 10863 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate" I0619 02:45:54.064901 10863 server.go:199] controller-runtime/webhook "msg"="serving webhook server" "host"="" "port"=35781 I0619 02:45:54.064970 10863 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" E0619 02:45:56.304122 10863 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="cluster-cache-test-qrw4j/test-cluster" [32m•[0mE0619 02:45:56.765297 10863 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="the server could not find the requested resource" "cluster"="cluster-cache-test-wk6pl/test-cluster" [32m•[0mE0619 02:45:57.307853 10863 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:36839/?timeout=50ms: dial tcp 127.0.0.1:36839: connect: connection refused" "cluster"="cluster-cache-test-dqm25/test-cluster" [32m•[0mI0619 02:45:57.532784 10863 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","selector":{},"template":{"metadata":{},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}}}},"status":{}}} I0619 02:45:57.733363 10863 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" I0619 02:45:57.733447 10863 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I0619 02:45:57.733721 10863 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={} [32m•[0mI0619 02:45:58.265218 10863 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" I0619 02:45:58.281538 10863 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="cluster" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}} I0619 02:45:58.383035 10863 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" I0619 02:45:58.383104 10863 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1 [32m•[0mI0619 02:45:58.568094 10863 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0619 02:45:58.568226 10863 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E0619 02:45:58.636992 10863 reflector.go:309] pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: Failed to watch *v1alpha3.Cluster: Get http://127.0.0.1:39161/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=143&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:39161: connect: connection refused [1m[32mRan 5 of 5 Specs in 16.379 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (16.38s) PASS ok sigs.k8s.io/cluster-api/controllers/remote 16.632s ? sigs.k8s.io/cluster-api/controllers/remote/fake [no test files] ? sigs.k8s.io/cluster-api/controlplane/kubeadm [no test files] === RUN TestKubeadmControlPlaneDefault ... skipping 208 lines ... === RUN TestReconcileNoClusterOwnerRef I0619 02:46:06.642869 11559 controller.go:130] "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" --- PASS: TestReconcileNoClusterOwnerRef (0.00s) === RUN TestReconcileNoKCP --- PASS: TestReconcileNoKCP (0.00s) === RUN TestReconcileNoCluster E0619 02:46:06.644139 11559 controller.go:126] "msg"="Failed to retrieve owner Cluster from the API Server" "error"="clusters.cluster.x-k8s.io \"foo\" not found" "kubeadmControlPlane"="foo" "namespace"="test" --- PASS: TestReconcileNoCluster (0.00s) === RUN TestReconcilePaused I0619 02:46:06.644717 11559 controller.go:136] "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" I0619 02:46:06.644851 11559 controller.go:136] "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" --- PASS: TestReconcilePaused (0.00s) === RUN TestReconcileClusterNoEndpoints ... skipping 192 lines ... --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s) === RUN TestPreflightChecks === RUN TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass === RUN TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue I0619 02:46:21.869805 11559 scale.go:173] "msg"="Waiting for machines to be deleted" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "Machines"="" === RUN TestPreflightChecks/control_plane_with_an_unhealthy_machine_condition_should_requeue I0619 02:46:21.869922 11559 scale.go:212] "msg"="Waiting for control plane to pass preflight checks" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "failures"="machine reports APIServerPodHealthy condition is false (Error, )" === RUN TestPreflightChecks/control_plane_with_an_healthy_machine_and_an_healthy_kcp_condition_should_pass --- PASS: TestPreflightChecks (0.00s) --- PASS: TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass (0.00s) --- PASS: TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue (0.00s) --- PASS: TestPreflightChecks/control_plane_with_an_unhealthy_machine_condition_should_requeue (0.00s) --- PASS: TestPreflightChecks/control_plane_with_an_healthy_machine_and_an_healthy_kcp_condition_should_pass (0.00s) ... skipping 18 lines ... === RUN TestAPIs Running Suite: Controller Suite =============================== Random Seed: [1m1655606753[0m Will run [1m1[0m of [1m1[0m specs E0619 02:46:21.903176 11559 controller.go:126] "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-5to6u2\" not found" "kubeadmControlPlane"="kcp-foo-5to6u2" "namespace"="test" [32m•[0m [1m[32mRan 1 of 1 Specs in 0.030 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (0.03s) === RUN TestKubeadmControlPlaneReconciler_upgradeControlPlane I0619 02:46:21.904324 11559 controller.go:246] "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-s3affd" "kubeadmControlPlane"="kcp-foo-s3affd" "namespace"="test" I0619 02:46:23.568983 11559 controller.go:331] "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-s3affd" "kubeadmControlPlane"="kcp-foo-s3affd" "namespace"="test" "needRollout"=["kcp-foo-s3affd-blxts"] I0619 02:46:23.569267 11559 scale.go:212] "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-s3affd" "kubeadmControlPlane"="kcp-foo-s3affd" "namespace"="test" "failures"="[machine kcp-foo-s3affd-v8hhk does not have APIServerPodHealthy condition, machine kcp-foo-s3affd-v8hhk does not have ControllerManagerPodHealthy condition, machine kcp-foo-s3affd-v8hhk does not have SchedulerPodHealthy condition, machine kcp-foo-s3affd-v8hhk does not have EtcdPodHealthy condition, machine kcp-foo-s3affd-v8hhk does not have EtcdMemberHealthy condition]" --- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (1.67s) ... skipping 60 lines ... ================================== Random Seed: [1m1655606752[0m Will run [1m7[0m of [1m7[0m specs [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m [1m[32mRan 7 of 7 Specs in 0.000 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m7 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestControlPlane (0.00s) === RUN TestHasUnhealthyMachine --- PASS: TestHasUnhealthyMachine (0.00s) === RUN TestNewFailureDomainPicker === RUN TestNewFailureDomainPicker/simple === RUN TestNewFailureDomainPicker/no_machines ... skipping 111 lines ... ======================================= Random Seed: [1m1655606752[0m Will run [1m7[0m of [1m7[0m specs [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m [1m[32mRan 7 of 7 Specs in 0.000 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m7 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestMachineCollection (0.00s) === RUN TestUpdateEtcdConditions === RUN TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown === RUN TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines === RUN TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines === RUN TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition ... skipping 297 lines ... --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s) --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s) === RUN TestRemoveMachineFromKubeadmConfigMap === RUN TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil === RUN TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil === RUN TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0 E0619 02:46:07.219779 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:46:15.543060 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:46:24.529072 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:46:35.659450 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:46:52.132661 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:47:05.141203 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:47:22.788657 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:47:43.712017 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:48:14.728531 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E0619 02:48:59.885687 11519 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" === RUN TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0 === RUN TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0 === RUN TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0 --- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s) --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s) --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s) ... skipping 83 lines ... --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_<_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s) PASS E0619 02:48:59.894409 11519 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" I0619 02:48:59.894489 11519 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E0619 02:48:59.894638 11519 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-101473715/tls.crt: no such file or directory" ok sigs.k8s.io/cluster-api/controlplane/kubeadm/internal 187.922s === RUN TestEtcdMembers_WithErrors --- PASS: TestEtcdMembers_WithErrors (0.00s) === RUN TestEtcdMembers_WithSuccess --- PASS: TestEtcdMembers_WithSuccess (0.00s) PASS ... skipping 287 lines ... I0619 02:46:14.759519 11885 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1 I0619 02:46:14.763501 11885 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}} I0619 02:46:14.863961 11885 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}} I0619 02:46:14.964400 11885 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" I0619 02:46:14.964474 11885 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1 I0619 02:46:15.049049 11885 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-op102r"} E0619 02:46:15.088457 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mI0619 02:46:16.123188 11885 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-z9b9qw"} E0619 02:46:16.163137 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mE0619 02:46:17.236497 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" E0619 02:46:18.259709 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mE0619 02:46:19.462678 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" E0619 02:46:20.503091 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset2\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset2" "namespace"="default" [32m•[0mE0619 02:46:21.518765 11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mI0619 02:46:21.522175 11885 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" I0619 02:46:21.522266 11885 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" E0619 02:46:21.522286 11885 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E0619 02:46:21.522322 11885 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-376741312/tls.crt: no such file or directory" I0619 02:46:21.522440 11885 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 5 of 5 Specs in 19.685 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (19.69s) PASS ok sigs.k8s.io/cluster-api/exp/addons/controllers 19.777s ? sigs.k8s.io/cluster-api/exp/addons/controllers/predicates [no test files] === RUN TestMachinePoolDefault === RUN TestMachinePoolDefault/for_MachinePool ... skipping 61 lines ... --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s) --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s) --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s) === RUN TestReconcileMachinePoolInfrastructure === RUN TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready === RUN TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed E0619 02:46:07.027584 12102 machinepool_controller_phases.go:237] "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" === RUN TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused --- PASS: TestReconcileMachinePoolInfrastructure (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s) === RUN TestMachinePoolFinalizer ... skipping 92 lines ... [32m•[0mI0619 02:46:18.338500 12102 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI0619 02:46:18.368470 12102 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI0619 02:46:18.388008 12102 machinepool_controller_phases.go:268] "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" [32m•[0mI0619 02:46:18.403041 12102 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinepool" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}} I0619 02:46:18.420474 12102 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI0619 02:46:18.443640 12102 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0m[32m•[0mE0619 02:46:18.446522 12102 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E0619 02:46:18.446575 12102 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-116006940/tls.crt: no such file or directory" E0619 02:46:18.446590 12102 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E0619 02:46:18.446607 12102 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-116006940/tls.crt: no such file or directory" I0619 02:46:18.446777 12102 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 9 of 9 Specs in 11.454 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m9 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (11.45s) PASS ok sigs.k8s.io/cluster-api/exp/controllers 11.724s ? sigs.k8s.io/cluster-api/exp/util [no test files] ? sigs.k8s.io/cluster-api/feature [no test files] ? sigs.k8s.io/cluster-api/hack/boilerplate/test [no test files] ... skipping 266 lines ... --- PASS: TestGetFirstReasonAndMessage (0.00s) === RUN TestNewConditionsGroup --- PASS: TestNewConditionsGroup (0.00s) === RUN TestMergeRespectPriority === RUN TestMergeRespectPriority/aggregate_nil_list_return_nil === RUN TestMergeRespectPriority/aggregate_empty_list_return_nil === RUN TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error === RUN TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning === RUN TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info === RUN TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info === RUN TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown === RUN TestMergeRespectPriority/nil_conditions_are_ignored --- PASS: TestMergeRespectPriority (0.00s) --- PASS: TestMergeRespectPriority/aggregate_nil_list_return_nil (0.00s) --- PASS: TestMergeRespectPriority/aggregate_empty_list_return_nil (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown (0.00s) --- PASS: TestMergeRespectPriority/nil_conditions_are_ignored (0.00s) === RUN TestNewPatch === RUN TestNewPatch/No_changes_return_empty_patch ... skipping 210 lines ... [90m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:39[0m Should patch a clusterv1.Cluster [90m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:411[0m [91m[1mupdating both spec, status, and adding a condition [It][0m [90m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:550[0m [91mExpected success, but got an error: <errors.aggregate | len:1, cap:1>: [ { ErrStatus: { TypeMeta: {Kind: "", APIVersion: ""}, ListMeta: { SelfLink: "", ... skipping 29 lines ... [32m•[0mI0619 02:46:42.148708 15045 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [91m[1mSummarizing 1 Failure:[0m [91m[1m[Fail] [0m[90mPatch Helper [0m[0mShould patch a clusterv1.Cluster [0m[91m[1m[It] updating both spec, status, and adding a condition [0m [37m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:580[0m [1m[91mRan 14 of 14 Specs in 7.663 seconds[0m [1m[91mFAIL![0m -- [32m[1m13 Passed[0m | [91m[1m1 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- FAIL: TestPatch (7.66s) === RUN TestToUnstructured === RUN TestToUnstructured/with_a_typed_object === RUN TestToUnstructured/with_an_unstructured_object --- PASS: TestToUnstructured (0.00s) --- PASS: TestToUnstructured/with_a_typed_object (0.00s) --- PASS: TestToUnstructured/with_an_unstructured_object (0.00s) ... skipping 2 lines ... === RUN TestUnsafeFocusedUnstructured/focus=status_w/_condition-setter_object,_should_only_return_status_(without_conditions)_and_common_fields === RUN TestUnsafeFocusedUnstructured/focus=status_w/o_condition-setter_object,_should_only_return_status_and_common_fields --- PASS: TestUnsafeFocusedUnstructured (0.00s) --- PASS: TestUnsafeFocusedUnstructured/focus=spec,_should_only_return_spec_and_common_fields (0.00s) --- PASS: TestUnsafeFocusedUnstructured/focus=status_w/_condition-setter_object,_should_only_return_status_(without_conditions)_and_common_fields (0.00s) --- PASS: TestUnsafeFocusedUnstructured/focus=status_w/o_condition-setter_object,_should_only_return_status_and_common_fields (0.00s) FAIL FAIL sigs.k8s.io/cluster-api/util/patch 7.698s ? sigs.k8s.io/cluster-api/util/predicates [no test files] ? sigs.k8s.io/cluster-api/util/record [no test files] === RUN TestSortForCreate --- PASS: TestSortForCreate (0.00s) PASS ok sigs.k8s.io/cluster-api/util/resource 0.022s ... skipping 88 lines ... --- PASS: TestToUnstructured/returns_error_for_invalid_yaml#01 (0.00s) --- PASS: TestToUnstructured/returns_error_for_invalid_yaml#02 (0.00s) === RUN TestFromUnstructured --- PASS: TestFromUnstructured (0.00s) PASS ok sigs.k8s.io/cluster-api/util/yaml 0.032s FAIL make: *** [Makefile:116: test] Error 1