periodic-cluster-api-test-release-0-3 #1535633124598222848
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 4m25s |
| Revision | release-0.3 |
... skipping 777 lines ... I0611 14:42:32.820525 8530 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" I0611 14:42:33.603913 8530 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•[0mI0611 14:42:33.626094 8530 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 1 of 1 Specs in 13.006 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (13.01s) PASS ok sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers 46.311s === RUN TestNewInitControlPlaneAdditionalFileEncodings --- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s) === 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.00s) === 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 1399 lines ... I0611 14:42:17.929018 10461 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinehealthcheck" I0611 14:42:17.929051 10461 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1 I0611 14:42:17.929086 10461 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I0611 14:42:17.929262 10461 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machine" "worker count"=1 I0611 14:42:17.930021 10461 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1 === RUN TestClusterReconcilePhases 2022/06/11 14:42:18 http: TLS handshake error from 127.0.0.1:58856: EOF === 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 I0611 14:42:18.028006 10461 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" I0611 14:42:18.036669 10461 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" === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infra_config_is_marked_for_deletion ... skipping 104 lines ... --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s) === RUN TestReconcileInfrastructure === RUN TestReconcileInfrastructure/new_machine,_infrastructure_config_ready I0611 14:42:18.063928 10461 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 I0611 14:42:18.066133 10461 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" E0611 14:42:18.066495 10461 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 I0611 14:42:18.066908 10461 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 I0611 14:42:18.298668 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={} E0611 14:42:18.301255 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I0611 14:42:18.311313 10461 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine" I0611 14:42:18.311432 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}} I0611 14:42:18.420937 10461 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine" I0611 14:42:18.421029 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}} I0611 14:42:18.521482 10461 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" "noderef"="node-1" E0611 14:42:18.533177 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" E0611 14:42:18.533224 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I0611 14:42:18.560364 10461 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" "noderef"="node-1" E0611 14:42:18.602851 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-ctm2w\" in namespace \"test-machine-watches-sh4nc\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" E0611 14:42:19.607325 10461 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-ctm2w\" in namespace \"test-machine-watches-sh4nc\", requeuing: requeue in 1s" E0611 14:42:19.616123 10461 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-ctm2w\" in namespace \"test-machine-watches-sh4nc\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-ctm2w\" in namespace \"test-machine-watches-sh4nc\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" --- PASS: TestWatches (1.61s) === 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 I0611 14:42:19.847160 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-zqnsx" "namespace"="test-machine-watches-sh4nc" "count"=1 I0611 14:42:19.847229 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-zqnsx" "namespace"="test-machine-watches-sh4nc" "descendants"="Worker machines: machine-created-ctm2w" "indirect descendants count"=0 I0611 14:42:19.863299 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-zqnsx" "namespace"="test-machine-watches-sh4nc" "count"=1 I0611 14:42:19.863377 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-zqnsx" "namespace"="test-machine-watches-sh4nc" "descendants"="Worker machines: machine-created-ctm2w" "indirect descendants count"=0 I0611 14:42:20.616661 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-zqnsx" "machine"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"1823a5d4-2706-470e-8ba0-97821ba09c61","apiVersion":"v1"} E0611 14:42:20.688064 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-ctm2w\" not found" "controller"="machine" "name"="machine-created-ctm2w" "namespace"="test-machine-watches-sh4nc" E0611 14:42:21.746920 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-xcfcj\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-6jpk7\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-6jpk7: secrets \"machine-reconcile-6jpk7-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-xcfcj" "namespace"="default" I0611 14:42:22.747520 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-6jpk7" "machine"="machine-created-xcfcj" "namespace"="default" "cause"="noderef is nil" "node"=null I0611 14:42:22.781697 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-6jpk7" "machine"="machine-created-xcfcj" "namespace"="default" "cause"="noderef is nil" "node"=null I0611 14:42:22.802540 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-6jpk7" "machine"="machine-created-xcfcj" "namespace"="default" "cause"="noderef is nil" "node"=null E0611 14:42:22.843703 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-xcfcj\" not found" "controller"="machine" "name"="machine-created-xcfcj" "namespace"="default" --- PASS: TestMachine_Reconcile (3.18s) --- PASS: TestMachine_Reconcile/reconcile_create (3.18s) === 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) --- PASS: TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one (0.00s) --- PASS: TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer (0.00s) === RUN TestMachineOwnerReference === RUN TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta I0611 14:42:22.861165 10461 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine2" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0611 14:42:22.861270 10461 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine2" "namespace"="default" === RUN TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set E0611 14:42:22.876820 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-6jpk7\" not found" "controller"="cluster" "name"="machine-reconcile-6jpk7" "namespace"="default" I0611 14:42:22.878880 10461 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine3" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0611 14:42:22.879005 10461 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine3" "namespace"="default" === RUN TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner I0611 14:42:22.882441 10461 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine4" "namespace"="default" "err"="cannot create a metadata client without a rest config" I0611 14:42:22.882618 10461 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" --- PASS: TestMachineOwnerReference (0.02s) ... skipping 123 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 I0611 14:42:23.137208 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-csjzz" "namespace"="test-mhc-kn7c7" I0611 14:42:23.160892 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} E0611 14:42:23.161533 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-ssbk6\" not found" "cluster"="test-mhc-kn7c7/test-cluster-ssbk6" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value E0611 14:42:23.185512 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-csjzz\" not found" "controller"="machinehealthcheck" "name"="test-mhc-csjzz" "namespace"="test-mhc-kn7c7" === 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 I0611 14:42:24.187539 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-csjzz" "namespace"="test-mhc-kn7c7" I0611 14:42:24.187655 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xjmtp" "namespace"="test-mhc-jh5qm" I0611 14:42:24.187701 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8mvl6" "namespace"="test-mhc-lkltm" I0611 14:42:24.187737 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qzfhl" "namespace"="test-mhc-mws5z" I0611 14:42:24.212137 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0611 14:42:24.229570 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qzfhl" "namespace"="test-mhc-mws5z" I0611 14:42:24.273563 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qzfhl" "namespace"="test-mhc-mws5z" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones E0611 14:42:24.298146 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-mws5z/test-cluster-9vkzn" E0611 14:42:24.298482 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-9vkzn\" not found" "controller"="cluster" "name"="test-cluster-9vkzn" "namespace"="test-mhc-mws5z" I0611 14:42:24.307524 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fn44v" "namespace"="test-mhc-5pd54" I0611 14:42:24.321365 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0611 14:42:24.441753 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fn44v" "namespace"="test-mhc-5pd54" I0611 14:42:24.446923 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fn44v" "namespace"="test-mhc-5pd54" E0611 14:42:24.513813 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-5pd54/test-cluster-vfd5h" I0611 14:42:24.518352 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fn44v" "namespace"="test-mhc-5pd54" === RUN TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy I0611 14:42:24.638101 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" inframachine created: test-mhc-machine-infra-gxxkv I0611 14:42:24.673670 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-mzsks I0611 14:42:24.695947 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.705329 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.705678 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" I0611 14:42:24.724502 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.724910 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" I0611 14:42:24.732247 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.732616 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" I0611 14:42:24.746256 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.746640 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" I0611 14:42:24.764143 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.764578 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" I0611 14:42:24.770213 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.770679 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" node created: test-mhc-node-6dq66 E0611 14:42:24.791428 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-6dq66" E0611 14:42:24.791693 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6dq66, got []" "node"="test-mhc-node-6dq66" I0611 14:42:24.796001 10461 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" "noderef"="test-mhc-node-6dq66" E0611 14:42:24.822100 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-6dq66" E0611 14:42:24.822164 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-6dq66" E0611 14:42:24.822350 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6dq66, got []" "node"="test-mhc-node-6dq66" E0611 14:42:24.822388 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6dq66, got []" "node"="test-mhc-node-6dq66" I0611 14:42:24.824361 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" inframachine created: test-mhc-machine-infra-4rgj6 machine created: test-mhc-machine-b9c9w I0611 14:42:24.848030 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.853864 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.859806 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" ... skipping 49 lines ... I0611 14:42:24.993834 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:24.999038 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.000503 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.001707 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.002747 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.004048 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.004424 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-b9c9w/" I0611 14:42:25.014892 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.015395 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-b9c9w/" I0611 14:42:25.021616 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.022069 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-b9c9w/" I0611 14:42:25.045203 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.045901 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-b9c9w/" E0611 14:42:25.052284 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-j8zmp, got []" "node"="test-mhc-node-j8zmp" E0611 14:42:25.052682 10461 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-j8zmp" node created: test-mhc-node-j8zmp I0611 14:42:25.059989 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.060481 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-b9c9w/" I0611 14:42:25.066707 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.067181 10461 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-zgxv9/test-mhc-srfj2/test-mhc-machine-b9c9w/" I0611 14:42:25.080218 10461 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" "noderef"="test-mhc-node-j8zmp" I0611 14:42:25.082934 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.172039 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" Cleaning up nodes, machines and infra machines. I0611 14:42:25.196881 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:25.197409 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-zgxv9/test-mhc-srfj2/test-mhc-machine-mzsks/" E0611 14:42:25.250639 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-zgxv9/test-cluster-6d6jg" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine inframachine created: test-mhc-machine-infra-nmqj2 machine created: test-mhc-machine-mf2tl E0611 14:42:25.317856 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" E0611 14:42:25.331971 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-machine-watches-sh4nc/machine-reconcile-zqnsx" E0611 14:42:25.366153 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-srfj2\" not found" "controller"="machinehealthcheck" "name"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" E0611 14:42:26.334354 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:26.366493 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:26.400973 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0611 14:42:26.401306 10461 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-czp9p/test-mhc-gl5j4/test-mhc-machine-mf2tl/" E0611 14:42:26.408609 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mtg8w, got []" "node"="test-mhc-node-mtg8w" node created: test-mhc-node-mtg8w inframachine created: test-mhc-machine-infra-29rr8 I0611 14:42:26.438535 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-srfj2" "namespace"="test-mhc-zgxv9" I0611 14:42:26.438638 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" machine created: test-mhc-machine-xddjd I0611 14:42:26.487053 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" ... skipping 287 lines ... I0611 14:42:27.312366 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.314477 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.322350 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.327431 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.331955 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.334457 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" E0611 14:42:27.335857 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:27.336972 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.339199 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.341403 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.355878 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.358600 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:27.360908 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" ... skipping 364 lines ... I0611 14:42:28.371626 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.374219 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.376615 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.378415 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.380523 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.384570 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" E0611 14:42:28.385493 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:28.386871 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.388389 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.389871 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.391217 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.392551 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:28.393922 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" ... skipping 364 lines ... I0611 14:42:29.391743 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.394061 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.395203 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.396474 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.397542 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.398941 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.399319 10461 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-czp9p/test-mhc-gl5j4/test-mhc-machine-xddjd/" E0611 14:42:29.399323 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:29.409777 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.410264 10461 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-czp9p/test-mhc-gl5j4/test-mhc-machine-xddjd/" node created: test-mhc-node-64dvx E0611 14:42:29.474436 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-64dvx, got []" "node"="test-mhc-node-64dvx" I0611 14:42:29.481185 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" inframachine created: test-mhc-machine-infra-4c9qm machine created: test-mhc-machine-l9vgt I0611 14:42:29.498719 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.504976 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:29.506444 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" ... skipping 229 lines ... I0611 14:42:30.400742 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.403314 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.405928 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.408472 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.411163 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.413829 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" E0611 14:42:30.416777 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:30.416883 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.422370 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.424073 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.425490 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.435055 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:30.436684 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" ... skipping 213 lines ... I0611 14:42:31.445961 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.450960 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.454184 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.470396 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.472223 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.474317 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" E0611 14:42:31.505898 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:31.506336 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.508115 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.509818 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.511481 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.512985 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:31.532459 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" ... skipping 283 lines ... I0611 14:42:32.503304 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.507076 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.511149 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.515156 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.518780 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.521619 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" E0611 14:42:32.538827 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:32.539248 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.540066 10461 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-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/" I0611 14:42:32.552189 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.552731 10461 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-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/" E0611 14:42:32.636079 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tx2mm, got []" "node"="test-mhc-node-tx2mm" node created: test-mhc-node-tx2mm Cleaning up nodes, machines and infra machines. I0611 14:42:32.647061 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.647807 10461 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-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/test-mhc-node-tx2mm" I0611 14:42:32.667077 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.667610 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/" Cleaning up nodes, machines and infra machines. I0611 14:42:32.687816 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.688524 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-mf2tl/" I0611 14:42:32.702646 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-xddjd/" I0611 14:42:32.717127 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/" I0611 14:42:32.729962 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.730600 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-mf2tl/" I0611 14:42:32.731112 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-xddjd/" I0611 14:42:32.731591 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/" I0611 14:42:32.736970 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-svl29" "namespace"="test-mhc-czp9p" "count"=2 I0611 14:42:32.737057 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-svl29" "namespace"="test-mhc-czp9p" "descendants"="Worker machines: test-mhc-machine-mf2tl,test-mhc-machine-xddjd,test-mhc-machine-l9vgt" "indirect descendants count"=1 I0611 14:42:32.743190 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-svl29" "namespace"="test-mhc-czp9p" "count"=2 I0611 14:42:32.743426 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-svl29" "namespace"="test-mhc-czp9p" "descendants"="Worker machines: test-mhc-machine-mf2tl,test-mhc-machine-xddjd,test-mhc-machine-l9vgt" "indirect descendants count"=1 I0611 14:42:32.746551 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.750989 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-xddjd/" I0611 14:42:32.752106 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-l9vgt/" I0611 14:42:32.755707 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-czp9p/test-mhc-gl5j4/test-mhc-machine-mf2tl/" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy I0611 14:42:32.757301 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gl5j4" "namespace"="test-mhc-czp9p" I0611 14:42:32.782456 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" inframachine created: test-mhc-machine-infra-pd8zn machine created: test-mhc-machine-lsb7w I0611 14:42:32.820840 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} ... skipping 2 lines ... I0611 14:42:32.968813 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:33.010165 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:33.091142 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:33.252242 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:33.539512 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-svl29" "machine"="test-mhc-machine-xddjd" "namespace"="test-mhc-czp9p" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-64dvx"} I0611 14:42:33.573319 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:33.589067 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-xddjd\" not found" "controller"="machine" "name"="test-mhc-machine-xddjd" "namespace"="test-mhc-czp9p" I0611 14:42:34.214321 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:34.589479 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:35.495319 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:35.589983 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-svl29" "machine"="test-mhc-machine-l9vgt" "namespace"="test-mhc-czp9p" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-tx2mm"} E0611 14:42:35.651090 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-l9vgt\" not found" "controller"="machine" "name"="test-mhc-machine-l9vgt" "namespace"="test-mhc-czp9p" E0611 14:42:36.651470 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:37.655548 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-svl29" "machine"="test-mhc-machine-mf2tl" "namespace"="test-mhc-czp9p" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-mtg8w"} E0611 14:42:37.707032 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-mf2tl\" not found" "controller"="machine" "name"="test-mhc-machine-mf2tl" "namespace"="test-mhc-czp9p" E0611 14:42:37.765609 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-czp9p/test-cluster-svl29" I0611 14:42:38.056285 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:38.716090 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:38.724198 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:38.724205 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:38.746893 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:38.767633 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-vxxh2, got []" "node"="test-mhc-node-vxxh2" node created: test-mhc-node-vxxh2 I0611 14:42:38.778052 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" inframachine created: test-mhc-machine-infra-dpcm4 machine created: test-mhc-machine-94lst I0611 14:42:38.811604 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:38.989533 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:38.994663 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:39.015921 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:39.057330 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:39.138688 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:39.300238 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:39.623204 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:39.724609 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:40.266675 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.739911 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.747811 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.760828 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.768228 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.775998 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.782342 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:40.789893 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:40.819665 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" node created: test-mhc-node-vc65r E0611 14:42:40.836271 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-vc65r, got []" "node"="test-mhc-node-vc65r" I0611 14:42:40.843719 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" inframachine created: test-mhc-machine-infra-67vqm I0611 14:42:40.856109 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" machine created: test-mhc-machine-8gq8r I0611 14:42:40.860792 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.877833 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:40.883969 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:41.548084 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:41.790255 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:42.802373 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:42.820280 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:42.872053 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:42.884968 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:42.889155 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:42.899327 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:42.905170 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:42.905585 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:42.927717 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" E0611 14:42:42.974809 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cgrrr, got []" "node"="test-mhc-node-cgrrr" node created: test-mhc-node-cgrrr I0611 14:42:42.982587 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" Cleaning up nodes, machines and infra machines. I0611 14:42:43.004995 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:43.020032 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" Cleaning up nodes, machines and infra machines. ... skipping 5 lines ... inframachine created: test-mhc-machine-infra-plvrv machine created: test-mhc-machine-kwptc I0611 14:42:43.152297 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:43.200906 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0611 14:42:43.233432 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5fhrc" "namespace"="test-mhc-tfk9h" I0611 14:42:43.233554 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:43.906193 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:44.906826 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-btwhv" "machine"="test-mhc-machine-lsb7w" "namespace"="test-mhc-tfk9h" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-vxxh2"} E0611 14:42:44.966530 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-lsb7w\" not found" "controller"="machine" "name"="test-mhc-machine-lsb7w" "namespace"="test-mhc-tfk9h" I0611 14:42:45.967778 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-btwhv" "machine"="test-mhc-machine-94lst" "namespace"="test-mhc-tfk9h" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-vc65r"} E0611 14:42:46.012670 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-94lst\" not found" "controller"="machine" "name"="test-mhc-machine-94lst" "namespace"="test-mhc-tfk9h" I0611 14:42:47.013246 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-btwhv" "machine"="test-mhc-machine-8gq8r" "namespace"="test-mhc-tfk9h" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-cgrrr"} E0611 14:42:47.054858 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-8gq8r\" not found" "controller"="machine" "name"="test-mhc-machine-8gq8r" "namespace"="test-mhc-tfk9h" I0611 14:42:48.067675 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:48.072604 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:48.074096 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:48.094373 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-tfk9h/test-cluster-btwhv" E0611 14:42:48.169043 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4tmt2, got []" "node"="test-mhc-node-4tmt2" node created: test-mhc-node-4tmt2 I0611 14:42:48.177243 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" inframachine created: test-mhc-machine-infra-hq565 machine created: test-mhc-machine-6swgf I0611 14:42:48.194723 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:48.203104 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:49.072958 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:42:50.086093 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:50.093234 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:50.104719 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:50.112584 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:50.121621 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:50.129309 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:50.129616 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:50.199996 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-vbs6k, got []" "node"="test-mhc-node-vbs6k" node created: test-mhc-node-vbs6k I0611 14:42:50.206809 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" inframachine created: test-mhc-machine-infra-z4mss machine created: test-mhc-machine-8phbf I0611 14:42:50.237802 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:50.250233 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.153451 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.166985 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.176615 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.206897 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.211734 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.218580 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.222162 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" E0611 14:42:51.223572 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" Cleaning up nodes, machines and infra machines. I0611 14:42:51.325699 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" Cleaning up nodes, machines and infra machines. I0611 14:42:51.334086 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.334580 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-hcrwl/test-mhc-lgxh7/test-mhc-machine-kwptc/" I0611 14:42:51.361806 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:51.362419 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-hcrwl/test-mhc-lgxh7/test-mhc-machine-kwptc/" I0611 14:42:51.362836 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-hcrwl/test-mhc-lgxh7/test-mhc-machine-6swgf/" I0611 14:42:51.384316 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-8l7bl" "namespace"="test-mhc-hcrwl" "count"=2 I0611 14:42:51.384404 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-8l7bl" "namespace"="test-mhc-hcrwl" "descendants"="Worker machines: test-mhc-machine-kwptc,test-mhc-machine-6swgf,test-mhc-machine-8phbf" "indirect descendants count"=1 I0611 14:42:51.389462 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-8l7bl" "namespace"="test-mhc-hcrwl" "count"=2 I0611 14:42:51.389516 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-8l7bl" "namespace"="test-mhc-hcrwl" "descendants"="Worker machines: test-mhc-machine-kwptc,test-mhc-machine-6swgf,test-mhc-machine-8phbf" "indirect descendants count"=1 === 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 inframachine created: test-mhc-machine-infra-47rts machine created: test-mhc-machine-dwql6 E0611 14:42:51.556285 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-lgxh7\" not found" "controller"="machinehealthcheck" "name"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:52.224127 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-8l7bl" "machine"="test-mhc-machine-kwptc" "namespace"="test-mhc-hcrwl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-4tmt2"} E0611 14:42:52.285825 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-kwptc\" not found" "controller"="machine" "name"="test-mhc-machine-kwptc" "namespace"="test-mhc-hcrwl" I0611 14:42:52.556562 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:52.577600 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0611 14:42:52.596004 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lgxh7" "namespace"="test-mhc-hcrwl" I0611 14:42:52.596081 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:52.596842 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:52.598268 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" ... skipping 311 lines ... I0611 14:42:53.321627 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.323365 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.325342 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.327152 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.328902 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.330660 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" E0611 14:42:53.331470 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-6swgf\" not found" "controller"="machine" "name"="test-mhc-machine-6swgf" "namespace"="test-mhc-hcrwl" I0611 14:42:53.332390 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.334126 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.335854 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.337541 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.339267 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:53.341062 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" ... skipping 486 lines ... I0611 14:42:54.362407 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.365651 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.367425 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.369165 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.370914 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.373029 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" E0611 14:42:54.373079 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-8phbf\" not found" "controller"="machine" "name"="test-mhc-machine-8phbf" "namespace"="test-mhc-hcrwl" I0611 14:42:54.375537 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.377248 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.379118 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.380918 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.382524 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:54.384228 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" ... skipping 460 lines ... I0611 14:42:55.383262 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.384902 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.385651 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.386616 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.388326 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.390086 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.390579 10461 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-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/" E0611 14:42:55.390827 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" I0611 14:42:55.401188 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.401499 10461 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-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/" E0611 14:42:55.447780 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mhhz4, got []" "node"="test-mhc-node-mhhz4" node created: test-mhc-node-mhhz4 E0611 14:42:55.447996 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mhhz4, got []" "node"="test-mhc-node-mhhz4" I0611 14:42:55.460646 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.476542 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.489482 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.489853 10461 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-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/test-mhc-node-mhhz4" I0611 14:42:55.514121 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.514557 10461 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-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/test-mhc-node-mhhz4" I0611 14:42:55.518524 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.518775 10461 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-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/test-mhc-node-mhhz4" Cleaning up nodes, machines and infra machines. I0611 14:42:55.530378 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.530727 10461 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-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/test-mhc-node-mhhz4" I0611 14:42:55.532107 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.532372 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/" I0611 14:42:55.544132 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.544446 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/" I0611 14:42:55.552191 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.552615 10461 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-2xvjb/test-mhc-tzzqz/test-mhc-machine-dwql6/" I0611 14:42:55.567249 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-gs5kd" "namespace"="test-mhc-2xvjb" "descendants"="Worker machines: test-mhc-machine-dwql6" "indirect descendants count"=1 I0611 14:42:55.570822 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-gs5kd" "namespace"="test-mhc-2xvjb" "descendants"="Worker machines: test-mhc-machine-dwql6" "indirect descendants count"=1 === RUN TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted I0611 14:42:55.571382 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tzzqz" "namespace"="test-mhc-2xvjb" I0611 14:42:55.719206 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" "creating"=1 "need"=1 I0611 14:42:55.719258 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" I0611 14:42:55.729934 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-r8htk-88f6w\"" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" I0611 14:42:55.806217 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:42:55.824435 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0611 14:42:55.844267 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" E0611 14:42:56.391195 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" E0611 14:42:56.402738 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-hcrwl/test-cluster-8l7bl" I0611 14:42:56.844492 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:42:57.391771 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-gs5kd" "machine"="test-mhc-machine-dwql6" "namespace"="test-mhc-2xvjb" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-mhhz4"} E0611 14:42:57.442374 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-dwql6\" not found" "controller"="machine" "name"="test-mhc-machine-dwql6" "namespace"="test-mhc-2xvjb" I0611 14:42:57.845322 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:42:58.459756 10461 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" I0611 14:42:58.460071 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:42:58.463044 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:42:58.463864 10461 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" I0611 14:42:58.477260 10461 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" ... skipping 5 lines ... I0611 14:42:58.497607 10461 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:42:58.497648 10461 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:42:58.846409 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:42:59.497507 10461 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:42:59.497558 10461 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:43:00.000710 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:43:00.001170 10461 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-zttsw/test-mhc-fw8rv/mhc-ms-r8htk-88f6w/" I0611 14:43:00.009366 10461 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" I0611 14:43:00.019942 10461 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:43:00.019992 10461 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:43:00.021957 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:43:00.022267 10461 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-zttsw/test-mhc-fw8rv/mhc-ms-r8htk-88f6w/" I0611 14:43:00.026160 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:43:00.026494 10461 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-zttsw/test-mhc-fw8rv/mhc-ms-r8htk-88f6w/" I0611 14:43:00.026900 10461 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" I0611 14:43:00.047584 10461 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:43:00.047627 10461 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:43:00.072483 10461 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-hps8f" "namespace"="test-mhc-zttsw" "count"=1 I0611 14:43:00.072543 10461 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-hps8f" "namespace"="test-mhc-zttsw" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-r8htk" I0611 14:43:00.075613 10461 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-r8htk" "namespace"="test-mhc-zttsw" "machine"="mhc-ms-r8htk-88f6w" I0611 14:43:00.078622 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hps8f" "namespace"="test-mhc-zttsw" "descendants"="Machine sets: mhc-ms-r8htk;Worker machines: mhc-ms-r8htk-88f6w" "indirect descendants count"=1 I0611 14:43:00.079445 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fw8rv" "namespace"="test-mhc-zttsw" I0611 14:43:00.082743 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hps8f" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" "cause"="cluster is being deleted" "node"=null I0611 14:43:00.085077 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hps8f" "namespace"="test-mhc-zttsw" "descendants"="Worker machines: mhc-ms-r8htk-88f6w" "indirect descendants count"=1 === 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 I0611 14:43:00.133472 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hps8f" "machine"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" "cause"="cluster is being deleted" "node"=null E0611 14:43:00.182417 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-r8htk-88f6w\" not found" "controller"="machine" "name"="mhc-ms-r8htk-88f6w" "namespace"="test-mhc-zttsw" I0611 14:43:00.255303 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" inframachine created: test-mhc-machine-infra-j9c49 I0611 14:43:00.288028 10461 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-wwbs8 I0611 14:43:00.313244 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.324266 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" ... skipping 129 lines ... I0611 14:43:00.575729 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.577473 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.579288 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.581352 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.583195 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.585104 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" E0611 14:43:00.585285 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-2xvjb/test-cluster-gs5kd" I0611 14:43:00.591535 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.593753 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.595686 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.597530 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.599274 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:00.601097 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" ... skipping 276 lines ... I0611 14:43:01.186617 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.188370 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.190203 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.190848 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.192692 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.194484 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" E0611 14:43:01.194740 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" node created: test-mhc-node-kh4h5 E0611 14:43:01.203674 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kh4h5, got []" "node"="test-mhc-node-kh4h5" E0611 14:43:01.203673 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kh4h5, got []" "node"="test-mhc-node-kh4h5" I0611 14:43:01.228259 10461 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-wwbs8" "target"="test-mhc-grk7n/test-mhc-mtvgj/test-mhc-machine-wwbs8/" I0611 14:43:01.240058 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.259187 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.266946 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.270886 10461 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-wwbs8" "target"="test-mhc-grk7n/test-mhc-mtvgj/test-mhc-machine-wwbs8/test-mhc-node-kh4h5" I0611 14:43:01.289492 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" Cleaning up nodes, machines and infra machines. I0611 14:43:01.301840 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.311189 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.321683 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mtvgj" "namespace"="test-mhc-grk7n" I0611 14:43:01.326993 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-47hhv" "namespace"="test-mhc-grk7n" "descendants"="Worker machines: test-mhc-machine-wwbs8" "indirect descendants count"=1 ... skipping 305 lines ... I0611 14:43:02.237922 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.239672 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.241407 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.243146 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.249306 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.251274 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" E0611 14:43:02.251633 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-wwbs8\" not found" "controller"="machine" "name"="test-mhc-machine-wwbs8" "namespace"="test-mhc-grk7n" I0611 14:43:02.253123 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.254913 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.256905 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.258702 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.260531 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:02.262286 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" ... skipping 523 lines ... I0611 14:43:03.256162 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.258254 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.259251 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.259892 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.262155 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.263287 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" E0611 14:43:03.263518 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" I0611 14:43:03.267152 10461 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-ls9vf" "target"="test-mhc-g7cvt/test-mhc-rpl59/test-mhc-machine-ls9vf/" I0611 14:43:03.277848 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" E0611 14:43:03.300884 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-8d67n, got []" "node"="test-mhc-node-8d67n" E0611 14:43:03.300898 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-8d67n, got []" "node"="test-mhc-node-8d67n" E0611 14:43:03.300952 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-8d67n, got []" "node"="test-mhc-node-8d67n" node created: test-mhc-node-8d67n I0611 14:43:03.309564 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.331653 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.334436 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.343507 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.347285 10461 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-ls9vf" "target"="test-mhc-g7cvt/test-mhc-rpl59/test-mhc-machine-ls9vf/test-mhc-node-8d67n" I0611 14:43:03.367635 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.378167 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.399895 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" Cleaning up nodes, machines and infra machines. I0611 14:43:03.414865 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" I0611 14:43:03.420060 10461 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-ls9vf" "target"="test-mhc-g7cvt/test-mhc-rpl59/test-mhc-machine-ls9vf/" I0611 14:43:03.427603 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dgjjt" "namespace"="test-mhc-g7cvt" "descendants"="Worker machines: test-mhc-machine-ls9vf" "indirect descendants count"=1 I0611 14:43:03.431164 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dgjjt" "namespace"="test-mhc-g7cvt" "descendants"="Worker machines: test-mhc-machine-ls9vf" "indirect descendants count"=1 E0611 14:43:03.439280 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-rpl59\" not found" "controller"="machinehealthcheck" "name"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" --- PASS: TestMachineHealthCheck_Reconcile (40.43s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.17s) --- 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.03s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (0.93s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.24s) ... skipping 10 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.24s) --- 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 E0611 14:43:03.442594 10461 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 E0611 14:43:03.444004 10461 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 E0611 14:43:03.445848 10461 machinehealthcheck_controller.go:474] "msg"="expected a Node" "error"="incorrect type" "type"="handler.MapObject" === RUN TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node E0611 14:43:03.446121 10461 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 E0611 14:43:03.446521 10461 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 --- PASS: TestNodeToMachineHealthCheck (0.00s) --- PASS: TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node (0.00s) ... skipping 31 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 I0611 14:43:03.449311 10461 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine1/" I0611 14:43:03.449809 10461 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine2/" E0611 14:43:03.451269 10461 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 E0611 14:43:03.458733 10461 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 E0611 14:43:03.460173 10461 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 82 lines ... I0611 14:43:03.472556 10461 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•[0mI0611 14:43:03.473998 10461 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" I0611 14:43:03.474725 10461 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" I0611 14:43:03.475386 10461 machine_controller_phases.go:278] "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" I0611 14:43:03.475460 10461 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" [32m•[0mI0611 14:43:03.476008 10461 machine_controller.go:327] "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" E0611 14:43:03.477257 10461 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•[0mI0611 14:43:03.559961 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-pl962" "namespace"="ms-test" "creating"=2 "need"=2 I0611 14:43:03.560004 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-pl962" "namespace"="ms-test" I0611 14:43:03.575550 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-pl962-6mwbg\"" "machineset"="ms-pl962" "namespace"="ms-test" I0611 14:43:03.575620 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-pl962" "namespace"="ms-test" I0611 14:43:03.589794 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-pl962-xtv5b\"" "machineset"="ms-pl962" "namespace"="ms-test" I0611 14:43:03.702955 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-pl962" "namespace"="ms-test" "creating"=1 "need"=2 I0611 14:43:03.703005 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-pl962" "namespace"="ms-test" I0611 14:43:03.719159 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-pl962-cv5l7\"" "machineset"="ms-pl962" "namespace"="ms-test" E0611 14:43:03.810451 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.810451 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.810506 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.913663 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.913717 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.913663 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.913750 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.913663 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.913782 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-cv5l7-7zn4f, got []" "node"="ms-pl962-cv5l7-7zn4f" E0611 14:43:03.941384 10461 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-pl962-cv5l7-7zn4f for machine ms-test/ms-pl962-cv5l7: the cache is not started, can not read objects" "machineset"="ms-pl962" "namespace"="ms-test" E0611 14:43:03.947733 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.947736 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.948394 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.951303 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.951392 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.951678 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.951741 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.952073 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" E0611 14:43:03.952106 10461 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-pl962-xtv5b-lgj8v, got []" "node"="ms-pl962-xtv5b-lgj8v" I0611 14:43:04.071878 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-pl962-cv5l7,ms-pl962-xtv5b" "indirect descendants count"=2 [32m•[0mI0611 14:43:04.076635 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-pl962-cv5l7,ms-pl962-xtv5b" "indirect descendants count"=2 [32m•[0mE0611 14:43:04.194735 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-tf4gq\" not found" "controller"="cluster" "name"="test1-tf4gq" "namespace"="default" I0611 14:43:04.264022 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-dgjjt" "machine"="test-mhc-machine-ls9vf" "namespace"="test-mhc-g7cvt" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-8d67n"} E0611 14:43:04.296657 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-ls9vf\" not found" "controller"="machine" "name"="test-mhc-machine-ls9vf" "namespace"="test-mhc-g7cvt" I0611 14:43:04.439567 10461 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rpl59" "namespace"="test-mhc-g7cvt" E0611 14:43:05.214420 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-zttsw/test-cluster-hps8f" [32m•[0mI0611 14:43:05.323672 10461 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-586t8" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I0611 14:43:05.440913 10461 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-586t8" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E0611 14:43:05.445174 10461 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-586t8" "namespace"="default" E0611 14:43:06.458074 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" [32m•[0mE0611 14:43:07.470386 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-grk7n/test-cluster-47hhv" E0611 14:43:07.481567 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-lzvvk\" not found" "controller"="cluster" "name"="test3-lzvvk" "namespace"="default" E0611 14:43:08.482305 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" E0611 14:43:09.509126 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-g7cvt/test-cluster-dgjjt" E0611 14:43:09.509180 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" [32m•[0mI0611 14:43:10.509651 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-pl962-cv5l7,ms-pl962-xtv5b" "indirect descendants count"=2 E0611 14:43:10.513569 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-dqbtn: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-dqbtn" "namespace"="default" E0611 14:43:11.435672 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-mzsks\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-mzsks" "namespace"="test-mhc-zgxv9" E0611 14:43:11.514380 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" E0611 14:43:12.524345 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-dqbtn: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-dqbtn" "namespace"="default" [32m•[0mE0611 14:43:13.503888 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6d6jg\" for machine \"test-mhc-machine-b9c9w\" in namespace \"test-mhc-zgxv9\": Cluster.cluster.x-k8s.io \"test-cluster-6d6jg\" not found" "controller"="machine" "name"="test-mhc-machine-b9c9w" "namespace"="test-mhc-zgxv9" E0611 14:43:13.525053 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" E0611 14:43:14.525895 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-dqbtn: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-dqbtn" "namespace"="default" E0611 14:43:15.536259 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" I0611 14:43:15.613023 10461 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-g6lqq" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E0611 14:43:15.633300 10461 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-g6lqq" "namespace"="default" E0611 14:43:15.658896 10461 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-g6lqq" "namespace"="default" E0611 14:43:16.537246 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-dqbtn: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-dqbtn" "namespace"="default" I0611 14:43:16.678067 10461 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-g6lqq" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I0611 14:43:16.678352 10461 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-g6lqq" "namespace"="default" "noderef"="id-node-1" E0611 14:43:16.690465 10461 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-g6lqq" "namespace"="default" I0611 14:43:17.537871 10461 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-pl962-cv5l7,ms-pl962-xtv5b" "indirect descendants count"=2 E0611 14:43:17.543548 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-586t8: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-586t8" "namespace"="default" [90m------------------------------[0m [32m• [SLOW TEST:5.035 seconds][0m Cluster Reconciler [90m/home/prow/go/src/sigs.k8s.io/cluster-api/controllers/cluster_controller_test.go:45[0m Should successfully set Status.ControlPlaneInitialized on the cluster object if controlplane is ready ... skipping 2 lines ... I0611 14:43:17.649808 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2 I0611 14:43:17.649849 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.658670 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-nb5rk-6657c7fddb-hdn24\"" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.658745 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.668267 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-nb5rk-6657c7fddb-mqn2j\"" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.690992 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fl9tc" "machine"="test6-g6lqq" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"b381fe9a-fc9e-4ba9-8f04-713565551f35","apiVersion":"v1"} E0611 14:43:17.709596 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-g6lqq\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-g6lqq" "namespace"="default" I0611 14:43:17.743237 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2 I0611 14:43:17.743278 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.755308 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-nb5rk-6657c7fddb-r7xcv\"" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.755390 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.771562 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-nb5rk-6657c7fddb-mh4r7\"" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.852589 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3 I0611 14:43:17.852631 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.862865 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-nb5rk-6657c7fddb-npgd2\"" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" I0611 14:43:17.958639 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1 I0611 14:43:17.958732 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" I0611 14:43:17.970829 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-nb5rk-cdfc6fd6c-8krwr\"" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" E0611 14:43:18.087507 10461 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-nb5rk-cdfc6fd6c-8krwr-q9kf5 for machine md-test/md-nb5rk-cdfc6fd6c-8krwr: the cache is not started, can not read objects" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" I0611 14:43:18.114294 10461 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2 I0611 14:43:18.114330 10461 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0611 14:43:18.124490 10461 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "machine"="md-nb5rk-6657c7fddb-r7xcv" I0611 14:43:18.235143 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2 I0611 14:43:18.235200 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" I0611 14:43:18.245574 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-nb5rk-cdfc6fd6c-c4mg8\"" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" I0611 14:43:18.435124 10461 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1 I0611 14:43:18.435166 10461 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0611 14:43:18.442373 10461 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "machine"="md-nb5rk-6657c7fddb-mh4r7" I0611 14:43:18.463907 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3 I0611 14:43:18.463982 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" I0611 14:43:18.475077 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-nb5rk-cdfc6fd6c-htjh5\"" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" E0611 14:43:18.544365 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-dqbtn: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-dqbtn" "namespace"="default" I0611 14:43:18.670021 10461 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0 I0611 14:43:18.670061 10461 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0611 14:43:18.673964 10461 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-nb5rk-6657c7fddb" "namespace"="md-test" "machine"="md-nb5rk-6657c7fddb-npgd2" I0611 14:43:18.740866 10461 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fl9tc" "machine"="test6-g6lqq" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"b381fe9a-fc9e-4ba9-8f04-713565551f35","apiVersion":"v1"} E0611 14:43:18.741677 10461 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-g6lqq\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-g6lqq" "namespace"="default" I0611 14:43:18.800333 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1 I0611 14:43:18.800372 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-nb5rk-74d45c49c5" "namespace"="md-test" I0611 14:43:18.810941 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-nb5rk-74d45c49c5-9kbf8\"" "machineset"="md-nb5rk-74d45c49c5" "namespace"="md-test" I0611 14:43:18.934807 10461 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2 I0611 14:43:18.934846 10461 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" I0611 14:43:18.939105 10461 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "machine"="md-nb5rk-cdfc6fd6c-c4mg8" ... skipping 3 lines ... I0611 14:43:19.164403 10461 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1 I0611 14:43:19.164438 10461 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" I0611 14:43:19.169342 10461 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-nb5rk-cdfc6fd6c" "namespace"="md-test" "machine"="md-nb5rk-cdfc6fd6c-htjh5" I0611 14:43:19.283305 10461 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-nb5rk-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3 I0611 14:43:19.283375 10461 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-nb5rk-74d45c49c5" "namespace"="md-test" I0611 14:43:19.294412 10461 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-nb5rk-74d45c49c5-nrjwd\"" "machineset"="md-nb5rk-74d45c49c5" "namespace"="md-test" E0611 14:43:19.539162 10461 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="md-test/test-cluster" [32m•[0m [1m[32mRan 16 of 16 Specs in 16.081 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m16 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (16.08s) PASS Tearing down test suite E0611 14:43:19.542680 10461 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E0611 14:43:19.542721 10461 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-765296897/tls.crt: no such file or directory" E0611 14:43:19.542742 10461 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E0611 14:43:19.542762 10461 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-765296897/tls.crt: no such file or directory" I0611 14:43:19.543275 10461 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" I0611 14:43:19.543301 10461 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" I0611 14:43:19.543303 10461 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" I0611 14:43:19.543330 10461 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" I0611 14:43:19.543356 10461 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" I0611 14:43:19.543371 10461 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0611 14:43:19.543383 10461 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" E0611 14:43:19.578986 10461 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:32805/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1238&timeout=10s&timeoutSeconds=393&watch=true: dial tcp 127.0.0.1:32805: connect: connection refused E0611 14:43:19.579448 10461 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:32805/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1238&timeout=10s&timeoutSeconds=579&watch=true: dial tcp 127.0.0.1:32805: connect: connection refused ok sigs.k8s.io/cluster-api/controllers 73.029s === RUN TestGetResourceFound --- PASS: TestGetResourceFound (0.00s) === RUN TestGetResourceNotFound --- PASS: TestGetResourceNotFound (0.00s) === RUN TestCloneTemplateResourceNotFound ... skipping 265 lines ... [32m•[0mI0611 14:42:22.665744 10921 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0611 14:42:22.683133 10921 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":{}}} I0611 14:42:22.983768 10921 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" I0611 14:42:22.983845 10921 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I0611 14:42:22.983919 10921 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={} [32m•[0mI0611 14:42:23.517603 10921 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" E0611 14:42:25.576952 10921 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="cluster-cache-test-skkcb/test-cluster" [32m•[0mE0611 14:42:26.021732 10921 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="the server could not find the requested resource" "cluster"="cluster-cache-test-zhqrr/test-cluster" [32m•[0mE0611 14:42:26.556575 10921 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:43381/?timeout=50ms: dial tcp 127.0.0.1:43381: connect: connection refused" "cluster"="cluster-cache-test-bpcc7/test-cluster" [32m•[0mI0611 14:42:26.677819 10921 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E0611 14:42:26.723699 10921 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:45087/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:45087: connect: connection refused [1m[32mRan 5 of 5 Specs in 17.850 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (17.85s) PASS ok sigs.k8s.io/cluster-api/controllers/remote 18.016s ? 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 I0611 14:42:33.440976 11622 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 E0611 14:42:33.442476 11622 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 I0611 14:42:33.443072 11622 controller.go:136] "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" I0611 14:42:33.443220 11622 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 I0611 14:42:49.635443 11622 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 I0611 14:42:49.635571 11622 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: [1m1654958539[0m Will run [1m1[0m of [1m1[0m specs E0611 14:42:49.658881 11622 controller.go:126] "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-h5xkj1\" not found" "kubeadmControlPlane"="kcp-foo-h5xkj1" "namespace"="test" [32m•[0m [1m[32mRan 1 of 1 Specs in 0.020 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (0.02s) === RUN TestKubeadmControlPlaneReconciler_upgradeControlPlane I0611 14:42:49.660526 11622 controller.go:246] "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-8ne2ij" "kubeadmControlPlane"="kcp-foo-8ne2ij" "namespace"="test" I0611 14:42:52.313761 11622 controller.go:331] "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-8ne2ij" "kubeadmControlPlane"="kcp-foo-8ne2ij" "namespace"="test" "needRollout"=["kcp-foo-8ne2ij-5jhzn"] I0611 14:42:52.313949 11622 scale.go:212] "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-8ne2ij" "kubeadmControlPlane"="kcp-foo-8ne2ij" "namespace"="test" "failures"="[machine kcp-foo-8ne2ij-v67jj does not have APIServerPodHealthy condition, machine kcp-foo-8ne2ij-v67jj does not have ControllerManagerPodHealthy condition, machine kcp-foo-8ne2ij-v67jj does not have SchedulerPodHealthy condition, machine kcp-foo-8ne2ij-v67jj does not have EtcdPodHealthy condition, machine kcp-foo-8ne2ij-v67jj does not have EtcdMemberHealthy condition]" --- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.66s) ... skipping 60 lines ... ================================== Random Seed: [1m1654958538[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: [1m1654958538[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 E0611 14:42:31.070891 11564 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" E0611 14:42:39.393972 11564 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" E0611 14:42:48.379977 11564 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" E0611 14:42:59.510284 11564 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" E0611 14:43:15.983548 11564 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" E0611 14:43:28.992201 11564 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" E0611 14:43:46.639619 11564 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" E0611 14:44:07.562929 11564 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" E0611 14:44:38.579456 11564 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" E0611 14:45:23.736691 11564 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 383 lines ... I0611 14:42:41.958861 11900 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" I0611 14:42:42.057994 11900 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}} I0611 14:42:42.158377 11900 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" I0611 14:42:42.158463 11900 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1 I0611 14:42:42.160120 11900 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1 I0611 14:42:42.273501 11900 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-hh4jzu"} E0611 14:42:42.299351 11900 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•[0mI0611 14:42:43.396413 11900 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-0lz37e"} E0611 14:42:43.453816 11900 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•[0mE0611 14:42:44.502342 11900 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" E0611 14:42:45.525247 11900 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•[0mE0611 14:42:46.650860 11900 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•[0mE0611 14:42:47.704206 11900 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" E0611 14:42:48.722772 11900 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•[0mI0611 14:42:48.729525 11900 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" I0611 14:42:48.729699 11900 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" I0611 14:42:48.729759 11900 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" E0611 14:42:48.729854 11900 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed" E0611 14:42:48.729934 11900 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-169508731/tls.key: no such file or directory" [1m[32mRan 5 of 5 Specs in 21.266 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (21.27s) PASS ok sigs.k8s.io/cluster-api/exp/addons/controllers 21.339s ? 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 E0611 14:42:33.907239 12130 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.01s) --- 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.01s) === RUN TestMachinePoolFinalizer ... skipping 95 lines ... [32m•[0mI0611 14:42:44.924938 12130 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI0611 14:42:44.952702 12130 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0m[32m•[0mI0611 14:42:44.955246 12130 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 9 of 9 Specs in 11.009 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m9 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (11.01s) PASS ok sigs.k8s.io/cluster-api/exp/controllers 11.212s ? 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 24 lines ... [1mSTEP[0m: Creating a new patch helper [1mSTEP[0m: Updating the object spec [1mSTEP[0m: Updating the object status [1mSTEP[0m: Setting Ready condition [1mSTEP[0m: Patching the object [32m•[0mI0611 14:43:10.100996 15073 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E0611 14:43:10.101210 15073 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E0611 14:43:10.101285 15073 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-458405154/tls.crt: no such file or directory" [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 8.145 seconds[0m [1m[91mFAIL![0m -- [32m[1m13 Passed[0m | [91m[1m1 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- FAIL: TestPatch (8.15s) === 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 8.239s ? 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.013s ... 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.040s FAIL make: *** [Makefile:116: test] Error 1