periodic-cluster-api-test-release-0-3 #1538170733853675520
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 4m26s |
| Revision | release-0.3 |
... skipping 777 lines ... I0618 14:46:05.807126 8428 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" I0618 14:46:06.492802 8428 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•[0mI0618 14:46:06.509118 8428 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 1 of 1 Specs in 13.094 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (13.09s) PASS ok sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers 46.574s === 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 1408 lines ... I0618 14:45:51.841373 10478 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" I0618 14:45:51.844472 10478 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 I0618 14:45:51.844942 10478 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" === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_is_marked_ready_on_cluster I0618 14:45:51.846523 10478 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" 2022/06/18 14:45:51 http: TLS handshake error from 127.0.0.1:50390: EOF === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_infrastructure_has_the_paused_annotation I0618 14:45:51.848400 10478 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" === RUN TestClusterReconcilePhases/reconcile_kubeconfig === RUN TestClusterReconcilePhases/reconcile_kubeconfig/cluster_not_provisioned,_apiEndpoint_is_not_set === RUN TestClusterReconcilePhases/reconcile_kubeconfig/kubeconfig_secret_found === RUN TestClusterReconcilePhases/reconcile_kubeconfig/kubeconfig_secret_not_found,_should_requeue ... skipping 95 lines ... --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s) === RUN TestReconcileInfrastructure === RUN TestReconcileInfrastructure/new_machine,_infrastructure_config_ready I0618 14:45:51.919165 10478 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 I0618 14:45:51.921304 10478 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" E0618 14:45:51.921639 10478 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 I0618 14:45:51.922134 10478 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 I0618 14:45:52.163360 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={} E0618 14:45:52.165460 10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I0618 14:45:52.173361 10478 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine" I0618 14:45:52.173442 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}} I0618 14:45:52.283737 10478 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine" I0618 14:45:52.283825 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}} I0618 14:45:52.384339 10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "noderef"="node-1" E0618 14:45:52.415849 10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" E0618 14:45:52.415919 10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I0618 14:45:52.486948 10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "noderef"="node-1" E0618 14:45:52.517203 10478 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-gbftz\" in namespace \"test-machine-watches-f7xsh\", requeuing: requeue in 1s" E0618 14:45:52.531302 10478 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-gbftz\" in namespace \"test-machine-watches-f7xsh\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-gbftz\" in namespace \"test-machine-watches-f7xsh\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" --- PASS: TestWatches (0.62s) === 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 I0618 14:45:52.742604 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "count"=1 I0618 14:45:52.742671 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "descendants"="Worker machines: machine-created-gbftz" "indirect descendants count"=0 I0618 14:45:52.760448 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "count"=1 I0618 14:45:52.760515 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "descendants"="Worker machines: machine-created-gbftz" "indirect descendants count"=0 I0618 14:45:53.531878 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-dk7sc" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"d70be0ff-e837-44e6-8dd0-95a9d8d778bc","apiVersion":"v1"} E0618 14:45:53.587400 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-gbftz\" not found" "controller"="machine" "name"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" E0618 14:45:54.676578 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-djvlf\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-rvh8h\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-rvh8h: secrets \"machine-reconcile-rvh8h-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-djvlf" "namespace"="default" I0618 14:45:55.679652 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rvh8h" "machine"="machine-created-djvlf" "namespace"="default" "cause"="noderef is nil" "node"=null I0618 14:45:55.721291 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rvh8h" "machine"="machine-created-djvlf" "namespace"="default" "cause"="noderef is nil" "node"=null I0618 14:45:55.745374 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rvh8h" "machine"="machine-created-djvlf" "namespace"="default" "cause"="noderef is nil" "node"=null E0618 14:45:55.776815 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-djvlf\" not found" "controller"="machine" "name"="machine-created-djvlf" "namespace"="default" --- PASS: TestMachine_Reconcile (3.24s) --- PASS: TestMachine_Reconcile/reconcile_create (3.24s) === RUN TestMachineFinalizer === RUN TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one === RUN TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer --- PASS: TestMachineFinalizer (0.00s) ... skipping 6 lines ... === RUN TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set I0618 14:45:55.798920 10478 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" I0618 14:45:55.799004 10478 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 I0618 14:45:55.804026 10478 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" I0618 14:45:55.804143 10478 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" E0618 14:45:55.804322 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-rvh8h\" not found" "controller"="cluster" "name"="machine-reconcile-rvh8h" "namespace"="default" --- PASS: TestMachineOwnerReference (0.02s) --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.00s) --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s) --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s) === RUN TestReconcileRequest === RUN TestReconcileRequest/machine_should_be_created ... skipping 118 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 I0618 14:45:55.974070 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j79zw" "namespace"="test-mhc-5wdzr" I0618 14:45:55.999013 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} E0618 14:45:55.999515 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-fwtvz\" not found" "cluster"="test-mhc-5wdzr/test-cluster-fwtvz" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value === 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 E0618 14:45:56.105082 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-j79zw\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-j79zw\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-j79zw" "namespace"="test-mhc-5wdzr" I0618 14:45:57.105379 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9x4q7" "namespace"="test-mhc-6pl6p" I0618 14:45:57.105494 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4gzqd" "namespace"="test-mhc-78fhk" I0618 14:45:57.105531 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j79zw" "namespace"="test-mhc-5wdzr" I0618 14:45:57.105564 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" I0618 14:45:57.158163 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0618 14:45:57.197502 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" I0618 14:45:57.198336 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones I0618 14:45:57.211345 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" E0618 14:45:57.217774 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-svfx5/test-cluster-rhddt" E0618 14:45:57.220226 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-rhddt\" not found" "controller"="cluster" "name"="test-cluster-rhddt" "namespace"="test-mhc-svfx5" I0618 14:45:57.349600 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdhrl" "namespace"="test-mhc-4fwhh" I0618 14:45:57.372817 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0618 14:45:57.492336 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdhrl" "namespace"="test-mhc-4fwhh" E0618 14:45:57.570638 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-4fwhh/test-cluster-h54ts" === RUN TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy I0618 14:45:57.602059 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdhrl" "namespace"="test-mhc-4fwhh" I0618 14:45:57.634947 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" inframachine created: test-mhc-machine-infra-7cbwz I0618 14:45:57.649138 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-79z8r I0618 14:45:57.749752 10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-79z8r/" node created: test-mhc-node-p5qrk E0618 14:45:57.763607 10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-p5qrk" E0618 14:45:57.763610 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p5qrk, got []" "node"="test-mhc-node-p5qrk" inframachine created: test-mhc-machine-infra-n994s I0618 14:45:57.781494 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" machine created: test-mhc-machine-l4gnb I0618 14:45:57.799051 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.804966 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.806027 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" ... skipping 57 lines ... I0618 14:45:57.966433 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.967969 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.971059 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.972724 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.973704 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.976522 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.976908 10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/" I0618 14:45:57.992034 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.993065 10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/" I0618 14:45:57.994400 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:57.994817 10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/" I0618 14:45:58.000169 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:58.000825 10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/" node created: test-mhc-node-9n5qg E0618 14:45:58.003862 10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-9n5qg" E0618 14:45:58.004047 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-9n5qg, got []" "node"="test-mhc-node-9n5qg" I0618 14:45:58.007769 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:58.008191 10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/" I0618 14:45:58.014640 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:58.025690 10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" "noderef"="test-mhc-node-9n5qg" I0618 14:45:58.033425 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" Cleaning up nodes, machines and infra machines. I0618 14:45:58.043868 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:58.044373 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-5jr87/test-mhc-dhwgj/test-mhc-machine-79z8r/" I0618 14:45:58.053720 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-j7n9k" "machine"="test-mhc-machine-79z8r" "namespace"="test-mhc-5jr87" "cause"="no control plane members" "node"={"name":"test-mhc-node-p5qrk"} E0618 14:45:58.081796 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-5jr87/test-cluster-j7n9k" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine E0618 14:45:58.119949 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found" "controller"="machine" "name"="test-mhc-machine-79z8r" "namespace"="test-mhc-5jr87" E0618 14:45:58.179469 10478 machinehealthcheck_controller.go:167] controllers/MachineHealthCheck "msg"="Failed to reconcile MachineHealthCheck" "error"="failed to patch unhealthy machine status for machine: test-mhc-5jr87/test-mhc-machine-79z8r: [Machine.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found]" "cluster"="test-cluster-j7n9k" E0618 14:45:58.182059 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[failed to patch unhealthy machine status for machine: test-mhc-5jr87/test-mhc-machine-79z8r: [Machine.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found], machinehealthchecks.cluster.x-k8s.io \"test-mhc-dhwgj\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" inframachine created: test-mhc-machine-infra-gzgmf E0618 14:45:58.240887 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-machine-watches-f7xsh/machine-reconcile-dk7sc" machine created: test-mhc-machine-2vvn5 E0618 14:45:59.120296 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:45:59.182310 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" I0618 14:45:59.182417 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:45:59.195578 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0618 14:45:59.215762 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:45:59.216845 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:45:59.217493 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" ... skipping 417 lines ... I0618 14:46:00.124615 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.126718 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.127804 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.128448 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.130123 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.131750 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.131981 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/" E0618 14:46:00.132151 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:00.141189 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.141467 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/" E0618 14:46:00.188780 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fhrdq, got []" "node"="test-mhc-node-fhrdq" node created: test-mhc-node-fhrdq I0618 14:46:00.196558 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" inframachine created: test-mhc-machine-infra-zfnrb machine created: test-mhc-machine-fmpnv I0618 14:46:00.216371 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:00.222897 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" ... skipping 383 lines ... I0618 14:46:01.169038 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.172291 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.173325 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.174341 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.176477 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.178701 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" E0618 14:46:01.180140 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:01.180366 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.181513 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.182661 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.184001 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.185537 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:01.187170 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" ... skipping 351 lines ... I0618 14:46:02.181115 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.184187 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.187319 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.188358 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.189371 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.191492 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.191874 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/" I0618 14:46:02.204391 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.204860 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/" E0618 14:46:02.205811 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:02.205845 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:02.206174 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/" E0618 14:46:02.231603 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6274r, got []" "node"="test-mhc-node-6274r" node created: test-mhc-node-6274r I0618 14:46:02.238851 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" inframachine created: test-mhc-machine-infra-zx5h7 I0618 14:46:02.253596 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" machine created: test-mhc-machine-zpqhv I0618 14:46:02.259444 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" ... skipping 297 lines ... I0618 14:46:03.250616 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.252791 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.260175 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.262609 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.265457 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.271118 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" E0618 14:46:03.271884 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:03.272987 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.277246 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.280245 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.288833 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.294527 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:03.297515 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" ... skipping 218 lines ... I0618 14:46:04.282184 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.284976 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.287667 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.289183 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.290815 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.292978 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.293831 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/" I0618 14:46:04.307255 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.307825 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/" I0618 14:46:04.312579 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.313134 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/" E0618 14:46:04.313417 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" node created: test-mhc-node-xl9xn E0618 14:46:04.373696 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xl9xn, got []" "node"="test-mhc-node-xl9xn" I0618 14:46:04.382289 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.383133 10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/test-mhc-node-xl9xn" Cleaning up nodes, machines and infra machines. Cleaning up nodes, machines and infra machines. I0618 14:46:04.428827 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.429392 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/" I0618 14:46:04.484384 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.485989 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/" I0618 14:46:04.517493 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/" I0618 14:46:04.541238 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "count"=2 I0618 14:46:04.541321 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "descendants"="Worker machines: test-mhc-machine-2vvn5,test-mhc-machine-fmpnv,test-mhc-machine-zpqhv" "indirect descendants count"=1 I0618 14:46:04.541814 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/" I0618 14:46:04.545774 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "count"=2 I0618 14:46:04.545842 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "descendants"="Worker machines: test-mhc-machine-2vvn5,test-mhc-machine-fmpnv,test-mhc-machine-zpqhv" "indirect descendants count"=1 I0618 14:46:04.547485 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.548040 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/" I0618 14:46:04.548474 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/" I0618 14:46:04.548783 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy I0618 14:46:04.550665 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" I0618 14:46:04.584140 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" inframachine created: test-mhc-machine-infra-qv65q I0618 14:46:04.613524 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-hxhnt ... skipping 3 lines ... I0618 14:46:04.673580 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:04.722642 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:04.803747 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:04.964740 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:05.285838 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:05.314063 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nnnfc" "machine"="test-mhc-machine-zpqhv" "namespace"="test-mhc-s9c54" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xl9xn"} E0618 14:46:05.516714 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-zpqhv\" not found" "controller"="machine" "name"="test-mhc-machine-zpqhv" "namespace"="test-mhc-s9c54" I0618 14:46:05.926947 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:06.517257 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nnnfc" "machine"="test-mhc-machine-fmpnv" "namespace"="test-mhc-s9c54" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6274r"} E0618 14:46:06.566835 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fmpnv\" not found" "controller"="machine" "name"="test-mhc-machine-fmpnv" "namespace"="test-mhc-s9c54" I0618 14:46:07.208003 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:07.567389 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nnnfc" "machine"="test-mhc-machine-2vvn5" "namespace"="test-mhc-s9c54" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-fhrdq"} E0618 14:46:07.624862 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2vvn5\" not found" "controller"="machine" "name"="test-mhc-machine-2vvn5" "namespace"="test-mhc-s9c54" E0618 14:46:08.625283 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" E0618 14:46:09.558467 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-s9c54/test-cluster-nnnfc" I0618 14:46:09.633442 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" E0618 14:46:09.639990 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:09.640349 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" E0618 14:46:09.660633 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p9tq7, got []" "node"="test-mhc-node-p9tq7" node created: test-mhc-node-p9tq7 I0618 14:46:09.662511 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:09.667466 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" inframachine created: test-mhc-machine-infra-x57cc machine created: test-mhc-machine-2tm9l I0618 14:46:09.697565 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" ... skipping 6 lines ... I0618 14:46:10.349298 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.669573 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.678315 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.702602 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.712471 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.725762 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" E0618 14:46:10.732852 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:10.733065 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.756195 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" node created: test-mhc-node-kf48l E0618 14:46:10.796761 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kf48l, got []" "node"="test-mhc-node-kf48l" I0618 14:46:10.811158 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" inframachine created: test-mhc-machine-infra-8spmm I0618 14:46:10.824535 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" machine created: test-mhc-machine-92ppt I0618 14:46:10.831941 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:10.843188 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" ... skipping 4 lines ... I0618 14:46:11.777815 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.796216 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.800565 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.809786 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.814347 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.832240 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" E0618 14:46:11.841169 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-l4vng, got []" "node"="test-mhc-node-l4vng" node created: test-mhc-node-l4vng I0618 14:46:11.848308 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.860776 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" Cleaning up nodes, machines and infra machines. I0618 14:46:11.882408 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" Cleaning up nodes, machines and infra machines. I0618 14:46:11.935669 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lc4dp" "machine"="test-mhc-machine-2tm9l" "namespace"="test-mhc-j847l" "cause"="no control plane members" "node"={"name":"test-mhc-node-kf48l"} I0618 14:46:11.936472 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:11.963973 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "count"=3 I0618 14:46:11.964068 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "descendants"="Worker machines: test-mhc-machine-2tm9l,test-mhc-machine-92ppt,test-mhc-machine-hxhnt" "indirect descendants count"=0 === RUN TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout I0618 14:46:11.977805 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "count"=3 I0618 14:46:11.977867 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "descendants"="Worker machines: test-mhc-machine-hxhnt,test-mhc-machine-2tm9l,test-mhc-machine-92ppt" "indirect descendants count"=0 E0618 14:46:11.982408 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-84wwp\" not found" "controller"="machinehealthcheck" "name"="test-mhc-84wwp" "namespace"="test-mhc-j847l" inframachine created: test-mhc-machine-infra-849w5 E0618 14:46:12.001420 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2tm9l\" not found" "controller"="machine" "name"="test-mhc-machine-2tm9l" "namespace"="test-mhc-j847l" machine created: test-mhc-machine-sc48x I0618 14:46:12.986201 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" I0618 14:46:12.986313 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:13.001492 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0618 14:46:13.007397 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lc4dp" "machine"="test-mhc-machine-hxhnt" "namespace"="test-mhc-j847l" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-p9tq7"} I0618 14:46:13.024309 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:13.024983 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" E0618 14:46:13.056509 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hxhnt\" not found" "controller"="machine" "name"="test-mhc-machine-hxhnt" "namespace"="test-mhc-j847l" I0618 14:46:14.057071 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lc4dp" "machine"="test-mhc-machine-92ppt" "namespace"="test-mhc-j847l" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-l4vng"} E0618 14:46:14.126638 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-92ppt\" not found" "controller"="machine" "name"="test-mhc-machine-92ppt" "namespace"="test-mhc-j847l" I0618 14:46:15.136154 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:15.143446 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" E0618 14:46:15.144336 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" E0618 14:46:15.245358 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-khsz9, got []" "node"="test-mhc-node-khsz9" E0618 14:46:15.245605 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-khsz9, got []" "node"="test-mhc-node-khsz9" node created: test-mhc-node-khsz9 I0618 14:46:15.254233 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" inframachine created: test-mhc-machine-infra-n6sl7 I0618 14:46:15.272997 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:15.278472 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" machine created: test-mhc-machine-z6dt7 ... skipping 7 lines ... I0618 14:46:16.200137 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.206491 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.221845 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.249444 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.260848 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.268792 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" E0618 14:46:16.296383 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bq9mq, got []" "node"="test-mhc-node-bq9mq" E0618 14:46:16.296605 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bq9mq, got []" "node"="test-mhc-node-bq9mq" node created: test-mhc-node-bq9mq I0618 14:46:16.318560 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" inframachine created: test-mhc-machine-infra-vd7s8 I0618 14:46:16.340488 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" machine created: test-mhc-machine-x8gxm I0618 14:46:16.345732 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" ... skipping 8 lines ... I0618 14:46:16.444882 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.450666 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" Cleaning up nodes, machines and infra machines. I0618 14:46:16.466686 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.466948 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-8b58l" "machine"="test-mhc-machine-x8gxm" "namespace"="test-mhc-hp52r" "cause"="noderef is nil" "node"=null I0618 14:46:16.468406 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.468915 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-hp52r/test-mhc-fdrgq/test-mhc-machine-sc48x/" I0618 14:46:16.503586 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:16.504414 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-hp52r/test-mhc-fdrgq/test-mhc-machine-z6dt7/" === 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 I0618 14:46:16.532479 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "count"=3 I0618 14:46:16.532550 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "descendants"="Worker machines: test-mhc-machine-sc48x,test-mhc-machine-z6dt7,test-mhc-machine-x8gxm" "indirect descendants count"=0 I0618 14:46:16.540296 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "count"=3 I0618 14:46:16.540468 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "descendants"="Worker machines: test-mhc-machine-sc48x,test-mhc-machine-z6dt7,test-mhc-machine-x8gxm" "indirect descendants count"=0 E0618 14:46:16.548028 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x8gxm\" not found" "controller"="machine" "name"="test-mhc-machine-x8gxm" "namespace"="test-mhc-hp52r" I0618 14:46:16.635884 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-hp52r/test-mhc-fdrgq/test-mhc-machine-sc48x/" E0618 14:46:16.638588 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-fdrgq\" not found" "controller"="machinehealthcheck" "name"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" inframachine created: test-mhc-machine-infra-ctdv5 machine created: test-mhc-machine-vc22m E0618 14:46:16.991231 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-j847l/test-cluster-lc4dp" I0618 14:46:17.548595 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-8b58l" "machine"="test-mhc-machine-sc48x" "namespace"="test-mhc-hp52r" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-khsz9"} E0618 14:46:17.598877 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-sc48x\" not found" "controller"="machine" "name"="test-mhc-machine-sc48x" "namespace"="test-mhc-hp52r" I0618 14:46:17.638894 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" I0618 14:46:17.639004 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:17.651823 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0618 14:46:17.678430 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:17.679418 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:17.681491 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" ... skipping 433 lines ... I0618 14:46:18.637186 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.638982 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.640844 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.642756 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.644894 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.646781 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" E0618 14:46:18.647002 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-z6dt7\" not found" "controller"="machine" "name"="test-mhc-machine-z6dt7" "namespace"="test-mhc-hp52r" I0618 14:46:18.649965 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.652159 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.653980 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.656095 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.657848 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:18.659585 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" ... skipping 461 lines ... I0618 14:46:19.652473 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.654176 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.655854 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.656413 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.658915 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.660965 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.661216 10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/" E0618 14:46:19.661322 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:19.670570 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.670895 10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/" E0618 14:46:19.703717 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97t7l, got []" "node"="test-mhc-node-97t7l" node created: test-mhc-node-97t7l E0618 14:46:19.703977 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97t7l, got []" "node"="test-mhc-node-97t7l" I0618 14:46:19.715823 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.740161 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.745306 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.745675 10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/test-mhc-node-97t7l" I0618 14:46:19.760577 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.760963 10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/test-mhc-node-97t7l" I0618 14:46:19.765576 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.765944 10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/test-mhc-node-97t7l" Cleaning up nodes, machines and infra machines. I0618 14:46:19.770881 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:19.771218 10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/" I0618 14:46:19.785941 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p9bxg" "namespace"="test-mhc-ljjqd" "descendants"="Worker machines: test-mhc-machine-vc22m" "indirect descendants count"=1 I0618 14:46:19.789727 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p9bxg" "namespace"="test-mhc-ljjqd" "descendants"="Worker machines: test-mhc-machine-vc22m" "indirect descendants count"=1 === RUN TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted I0618 14:46:19.910316 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" I0618 14:46:20.008081 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" "creating"=1 "need"=1 I0618 14:46:20.008136 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:20.020341 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-gfj4m-w4mhl\"" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:20.090491 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:20.115008 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I0618 14:46:20.128300 10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:20.241089 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:20.661915 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-p9bxg" "machine"="test-mhc-machine-vc22m" "namespace"="test-mhc-ljjqd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-97t7l"} E0618 14:46:20.711306 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vc22m\" not found" "controller"="machine" "name"="test-mhc-machine-vc22m" "namespace"="test-mhc-ljjqd" I0618 14:46:21.241321 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" E0618 14:46:21.553946 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-hp52r/test-cluster-8b58l" I0618 14:46:21.720665 10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:21.720827 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:21.730161 10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:21.730327 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:21.745402 10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:21.745467 10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" ... skipping 3 lines ... I0618 14:46:21.765389 10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:21.767514 10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:21.767661 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:21.776094 10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:21.776138 10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:22.242349 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:22.242888 10478 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-vksgb/test-mhc-grqzq/mhc-ms-gfj4m-w4mhl/" I0618 14:46:22.251284 10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:22.258859 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:22.259291 10478 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-vksgb/test-mhc-grqzq/mhc-ms-gfj4m-w4mhl/" I0618 14:46:22.261666 10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:22.261701 10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:22.270051 10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:22.270149 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" I0618 14:46:22.270518 10478 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-vksgb/test-mhc-grqzq/mhc-ms-gfj4m-w4mhl/" I0618 14:46:22.279745 10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:22.279803 10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" I0618 14:46:22.345060 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "count"=1 I0618 14:46:22.345124 10478 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-gfj4m" I0618 14:46:22.349792 10478 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" "machine"="mhc-ms-gfj4m-w4mhl" I0618 14:46:22.350892 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "descendants"="Machine sets: mhc-ms-gfj4m;Worker machines: mhc-ms-gfj4m-w4mhl" "indirect descendants count"=1 I0618 14:46:22.354288 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" === 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 I0618 14:46:22.363449 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-r6n8p" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" "cause"="cluster is being deleted" "node"=null I0618 14:46:22.364141 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "descendants"="Worker machines: mhc-ms-gfj4m-w4mhl" "indirect descendants count"=1 E0618 14:46:22.381299 10478 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-gfj4m\" not found" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" E0618 14:46:22.381391 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-gfj4m\" not found" "controller"="machineset" "name"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" I0618 14:46:22.552594 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-r6n8p" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" "cause"="cluster is being deleted" "node"=null I0618 14:46:22.608921 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" E0618 14:46:22.609475 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-gfj4m-w4mhl\" not found" "controller"="machine" "name"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" inframachine created: test-mhc-machine-infra-7j5fq I0618 14:46:22.624137 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-x977p I0618 14:46:22.751098 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:22.752074 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:22.752717 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" ... skipping 393 lines ... I0618 14:46:23.620438 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.621670 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.622279 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.623432 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.625618 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.626486 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" E0618 14:46:23.641652 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" E0618 14:46:23.641653 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" node created: test-mhc-node-cv4q9 E0618 14:46:23.641888 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" I0618 14:46:23.641965 10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-x977p" "namespace"="test-mhc-4ccvs" "noderef"="test-mhc-node-cv4q9" E0618 14:46:23.646752 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" E0618 14:46:23.646790 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" E0618 14:46:23.646915 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" E0618 14:46:23.646938 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" E0618 14:46:23.646973 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" E0618 14:46:23.647029 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []" "node"="test-mhc-node-cv4q9" I0618 14:46:23.673464 10478 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-x977p" "target"="test-mhc-4ccvs/test-mhc-w9dqq/test-mhc-machine-x977p/" I0618 14:46:23.692358 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.715375 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.721773 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.725553 10478 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-x977p" "target"="test-mhc-4ccvs/test-mhc-w9dqq/test-mhc-machine-x977p/test-mhc-node-cv4q9" I0618 14:46:23.753999 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.757223 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" Cleaning up nodes, machines and infra machines. I0618 14:46:23.770517 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.774173 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" I0618 14:46:23.777237 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" ... skipping 4 lines ... === RUN TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted I0618 14:46:23.811818 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-mmw2c" "machine"="test-mhc-machine-x977p" "namespace"="test-mhc-4ccvs" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-cv4q9"} I0618 14:46:23.834684 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" inframachine created: test-mhc-machine-infra-gnhb8 I0618 14:46:23.859593 10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-f6b7n E0618 14:46:23.882746 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x977p\" not found" "controller"="machine" "name"="test-mhc-machine-x977p" "namespace"="test-mhc-4ccvs" I0618 14:46:23.977880 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:23.984009 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:23.985132 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:23.986946 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:23.988783 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:23.990568 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" ... skipping 348 lines ... I0618 14:46:24.801312 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.803012 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.804764 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.806475 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.808178 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.809903 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" E0618 14:46:24.810300 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-ljjqd/test-cluster-p9bxg" I0618 14:46:24.811614 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.822088 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.824251 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.826582 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.828665 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.830691 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" ... skipping 26 lines ... I0618 14:46:24.883835 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.885536 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.888171 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.890558 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.892842 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.895850 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" E0618 14:46:24.898216 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" I0618 14:46:24.898637 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:24.902173 10478 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-f6b7n" "target"="test-mhc-r4hcf/test-mhc-m7c7p/test-mhc-machine-f6b7n/" I0618 14:46:24.914434 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" E0618 14:46:24.971543 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bbr8n, got []" "node"="test-mhc-node-bbr8n" node created: test-mhc-node-bbr8n E0618 14:46:24.971637 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bbr8n, got []" "node"="test-mhc-node-bbr8n" E0618 14:46:24.971987 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bbr8n, got []" "node"="test-mhc-node-bbr8n" I0618 14:46:24.979571 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.013522 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.026560 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.036624 10478 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-f6b7n" "target"="test-mhc-r4hcf/test-mhc-m7c7p/test-mhc-machine-f6b7n/test-mhc-node-bbr8n" I0618 14:46:25.055551 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.067116 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.107314 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.110330 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" Cleaning up nodes, machines and infra machines. I0618 14:46:25.137645 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.140416 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:25.146521 10478 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-f6b7n" "target"="test-mhc-r4hcf/test-mhc-m7c7p/test-mhc-machine-f6b7n/" I0618 14:46:25.162913 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5h25r" "namespace"="test-mhc-r4hcf" "descendants"="Worker machines: test-mhc-machine-f6b7n" "indirect descendants count"=1 I0618 14:46:25.176399 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5h25r" "namespace"="test-mhc-r4hcf" "descendants"="Worker machines: test-mhc-machine-f6b7n" "indirect descendants count"=1 --- PASS: TestMachineHealthCheck_Reconcile (29.23s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.06s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.04s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.03s) ... skipping 12 lines ... --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s) machinehealthcheck_controller_test.go:933: skipping until made stable --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (1.44s) --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (1.38s) === RUN TestClusterToMachineHealthCheck === RUN TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster E0618 14:46:25.186656 10478 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 E0618 14:46:25.188256 10478 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 E0618 14:46:25.191543 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-m7c7p\" not found" "controller"="machinehealthcheck" "name"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" === RUN TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node E0618 14:46:25.193756 10478 machinehealthcheck_controller.go:474] "msg"="expected a Node" "error"="incorrect type" "type"="handler.MapObject" === RUN TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node E0618 14:46:25.194242 10478 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 E0618 14:46:25.203120 10478 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.02s) --- 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 I0618 14:46:25.206677 10478 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine1/" I0618 14:46:25.207319 10478 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine2/" E0618 14:46:25.209257 10478 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 E0618 14:46:25.222618 10478 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 E0618 14:46:25.224670 10478 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 65 lines ... I0618 14:46:25.361502 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-d5w72-c99mf\"" "machineset"="ms-d5w72" "namespace"="ms-test" I0618 14:46:25.361571 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-d5w72" "namespace"="ms-test" I0618 14:46:25.381432 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-d5w72-k8ftl\"" "machineset"="ms-d5w72" "namespace"="ms-test" I0618 14:46:25.452305 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-d5w72" "namespace"="ms-test" "creating"=1 "need"=2 I0618 14:46:25.452354 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-d5w72" "namespace"="ms-test" I0618 14:46:25.471835 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-d5w72-cv4rp\"" "machineset"="ms-d5w72" "namespace"="ms-test" E0618 14:46:25.569352 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.569512 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.569550 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.681041 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.681103 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.681532 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.681570 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.682330 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.682369 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []" "node"="ms-d5w72-cv4rp-xrp2g" E0618 14:46:25.748340 10478 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-d5w72-cv4rp-xrp2g for machine ms-test/ms-d5w72-cv4rp: the cache is not started, can not read objects" "machineset"="ms-d5w72" "namespace"="ms-test" E0618 14:46:25.751318 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.751572 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.751847 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.856057 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.856123 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.856125 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.856178 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.856301 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" E0618 14:46:25.856342 10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []" "node"="ms-d5w72-k8ftl-xbdv9" I0618 14:46:25.898787 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5h25r" "machine"="test-mhc-machine-f6b7n" "namespace"="test-mhc-r4hcf" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-bbr8n"} E0618 14:46:25.943701 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-f6b7n\" not found" "controller"="machine" "name"="test-mhc-machine-f6b7n" "namespace"="test-mhc-r4hcf" I0618 14:46:25.981112 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-cv4rp,ms-d5w72-k8ftl" "indirect descendants count"=2 [32m•[0mI0618 14:46:25.985927 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-cv4rp,ms-d5w72-k8ftl" "indirect descendants count"=2 [32m•[0mE0618 14:46:26.115688 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-s7cnh\" not found" "controller"="cluster" "name"="test1-s7cnh" "namespace"="default" I0618 14:46:26.191795 10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" I0618 14:46:27.238277 10478 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-ssgl2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" [32m•[0mI0618 14:46:27.358470 10478 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-ssgl2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E0618 14:46:27.363878 10478 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-ssgl2" "namespace"="default" E0618 14:46:28.386595 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-vksgb/test-cluster-r6n8p" E0618 14:46:28.391668 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" [32m•[0mE0618 14:46:29.416578 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-tpdc2\" not found" "controller"="cluster" "name"="test3-tpdc2" "namespace"="default" E0618 14:46:30.417429 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" E0618 14:46:31.443082 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-4ccvs/test-cluster-mmw2c" E0618 14:46:31.452604 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" E0618 14:46:31.453219 10478 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-r4hcf/test-cluster-5h25r" [32m•[0mI0618 14:46:32.453168 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-cv4rp,ms-d5w72-k8ftl" "indirect descendants count"=2 E0618 14:46:32.458776 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-cv89s: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default" E0618 14:46:33.459596 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" E0618 14:46:34.470626 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-cv89s: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default" [32m•[0mE0618 14:46:35.138531 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" E0618 14:46:35.471280 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" E0618 14:46:36.472098 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-cv89s: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default" E0618 14:46:37.485902 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" I0618 14:46:37.586858 10478 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bqc6v" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E0618 14:46:37.599147 10478 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-bqc6v" "namespace"="default" E0618 14:46:37.613231 10478 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-bqc6v" "namespace"="default" E0618 14:46:38.486592 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-cv89s: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default" I0618 14:46:38.627511 10478 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bqc6v" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I0618 14:46:38.627726 10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-bqc6v" "namespace"="default" "noderef"="id-node-1" E0618 14:46:38.639455 10478 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-bqc6v" "namespace"="default" I0618 14:46:39.487177 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-k8ftl,ms-d5w72-cv4rp" "indirect descendants count"=2 E0618 14:46:39.491208 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" [90m------------------------------[0m [32m• [SLOW TEST:5.042 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 21 lines ... I0618 14:46:39.602645 10478 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•[0mI0618 14:46:39.604169 10478 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" I0618 14:46:39.604889 10478 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" I0618 14:46:39.605572 10478 machine_controller_phases.go:278] "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" I0618 14:46:39.605645 10478 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" [32m•[0mI0618 14:46:39.606307 10478 machine_controller.go:327] "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" E0618 14:46:39.607773 10478 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•[0mI0618 14:46:39.639899 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fhw7d" "machine"="test6-bqc6v" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"876c9568-c74b-4a11-a87f-df1329f641f7","apiVersion":"v1"} E0618 14:46:39.660097 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-bqc6v\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-bqc6v" "namespace"="default" I0618 14:46:39.664046 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2 I0618 14:46:39.664120 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" I0618 14:46:39.678792 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-b2dbw-6657c7fddb-g6ftt\"" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" I0618 14:46:39.678905 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" I0618 14:46:39.693787 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-b2dbw-6657c7fddb-v2s8t\"" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" I0618 14:46:39.807182 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2 ... skipping 4 lines ... I0618 14:46:39.911741 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3 I0618 14:46:39.911784 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" I0618 14:46:39.926144 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-6657c7fddb-x7jdb\"" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" I0618 14:46:40.010453 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1 I0618 14:46:40.010508 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" I0618 14:46:40.020200 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-cdfc6fd6c-2gqwf\"" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" E0618 14:46:40.143310 10478 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-b2dbw-cdfc6fd6c-2gqwf-dwcnf for machine md-test/md-b2dbw-cdfc6fd6c-2gqwf: the cache is not started, can not read objects" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" I0618 14:46:40.178534 10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2 I0618 14:46:40.178570 10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0618 14:46:40.183902 10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "machine"="md-b2dbw-6657c7fddb-w67kc" I0618 14:46:40.203904 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2 I0618 14:46:40.203986 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" I0618 14:46:40.213386 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-cdfc6fd6c-v7llc\"" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" I0618 14:46:40.403283 10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1 I0618 14:46:40.403317 10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0618 14:46:40.407020 10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "machine"="md-b2dbw-6657c7fddb-845qh" E0618 14:46:40.491892 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-cv89s: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default" I0618 14:46:40.557016 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3 I0618 14:46:40.557092 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" I0618 14:46:40.570098 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-cdfc6fd6c-g8q8h\"" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" I0618 14:46:40.671454 10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fhw7d" "machine"="test6-bqc6v" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"876c9568-c74b-4a11-a87f-df1329f641f7","apiVersion":"v1"} E0618 14:46:40.672683 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-bqc6v\" in namespace \"default\": failed to retrieve external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-bqc6v" "namespace"="default" I0618 14:46:40.730098 10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0 I0618 14:46:40.730138 10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I0618 14:46:40.734513 10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "machine"="md-b2dbw-6657c7fddb-x7jdb" I0618 14:46:40.869773 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1 I0618 14:46:40.869828 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" I0618 14:46:40.881022 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-74d45c49c5-qlqj5\"" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" ... skipping 8 lines ... I0618 14:46:41.366114 10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "machine"="md-b2dbw-cdfc6fd6c-g8q8h" I0618 14:46:41.477376 10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3 I0618 14:46:41.477419 10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" I0618 14:46:41.488315 10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-74d45c49c5-wbxfm\"" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" I0618 14:46:41.492570 10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-fhw7d" "namespace"="default" "count"=1 I0618 14:46:41.492662 10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-fhw7d" "namespace"="default" "descendants"="Control plane machines: test6-bqc6v" "indirect descendants count"=0 E0618 14:46:41.509646 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default" [32m•[0m [1m[32mRan 16 of 16 Specs in 16.396 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m16 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (16.40s) PASS Tearing down test suite I0618 14:46:41.622172 10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" I0618 14:46:41.622223 10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" I0618 14:46:41.622244 10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" I0618 14:46:41.622276 10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0618 14:46:41.622298 10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" I0618 14:46:41.622317 10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0618 14:46:41.622396 10478 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E0618 14:46:41.622843 10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-b2dbw\" not found" "controller"="machinedeployment" "name"="md-b2dbw" "namespace"="md-test" I0618 14:46:41.624141 10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0 I0618 14:46:41.624180 10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" I0618 14:46:41.628781 10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "machine"="md-b2dbw-cdfc6fd6c-2gqwf" E0618 14:46:41.629296 10478 event.go:272] Unable to write event: 'Post http://127.0.0.1:42473/api/v1/namespaces/md-test/events: dial tcp 127.0.0.1:42473: connect: connection refused' (may retry after sleeping) E0618 14:46:41.665045 10478 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:42473/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1267&timeout=10s&timeoutSeconds=522&watch=true: dial tcp 127.0.0.1:42473: connect: connection refused E0618 14:46:41.665453 10478 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:42473/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1267&timeout=10s&timeoutSeconds=540&watch=true: dial tcp 127.0.0.1:42473: connect: connection refused E0618 14:46:41.665453 10478 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:42473/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1267&timeout=10s&timeoutSeconds=519&watch=true: dial tcp 127.0.0.1:42473: connect: connection refused ok sigs.k8s.io/cluster-api/controllers 61.929s === RUN TestGetResourceFound --- PASS: TestGetResourceFound (0.00s) === RUN TestGetResourceNotFound --- PASS: TestGetResourceNotFound (0.00s) === RUN TestCloneTemplateResourceNotFound ... skipping 256 lines ... I0618 14:45:53.118113 10939 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook" "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset" I0618 14:45:53.118134 10939 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset" I0618 14:45:53.118323 10939 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server" I0618 14:45:53.119381 10939 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate" I0618 14:45:53.119625 10939 server.go:199] controller-runtime/webhook "msg"="serving webhook server" "host"="" "port"=39913 I0618 14:45:53.119885 10939 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" E0618 14:45:55.489642 10939 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="cluster-cache-test-h8nfg/test-cluster" [32m•[0mE0618 14:45:55.955083 10939 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="the server could not find the requested resource" "cluster"="cluster-cache-test-k8t8p/test-cluster" [32m•[0mE0618 14:45:56.490173 10939 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:46431/?timeout=50ms: dial tcp 127.0.0.1:46431: connect: connection refused" "cluster"="cluster-cache-test-v49wc/test-cluster" [32m•[0mI0618 14:45:56.739614 10939 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="cluster" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}} I0618 14:45:56.840546 10939 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" I0618 14:45:56.840612 10939 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1 [32m•[0mI0618 14:45:57.019256 10939 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I0618 14:45:57.029457 10939 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":{}}} I0618 14:45:57.229944 10939 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" I0618 14:45:57.230006 10939 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I0618 14:45:57.230077 10939 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={} [32m•[0mI0618 14:45:57.756665 10939 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" I0618 14:45:57.756698 10939 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" E0618 14:45:57.816712 10939 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:42037/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:42037: connect: connection refused [1m[32mRan 5 of 5 Specs in 16.066 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (16.07s) PASS ok sigs.k8s.io/cluster-api/controllers/remote 16.210s ? 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 I0618 14:46:06.067180 11553 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 E0618 14:46:06.068468 11553 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 I0618 14:46:06.069062 11553 controller.go:136] "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" I0618 14:46:06.069212 11553 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 I0618 14:46:20.964811 11553 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 I0618 14:46:20.965000 11553 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: [1m1655563551[0m Will run [1m1[0m of [1m1[0m specs E0618 14:46:20.996411 11553 controller.go:126] "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-ltuo3n\" not found" "kubeadmControlPlane"="kcp-foo-ltuo3n" "namespace"="test" [32m•[0m [1m[32mRan 1 of 1 Specs in 0.027 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (0.03s) === RUN TestKubeadmControlPlaneReconciler_upgradeControlPlane I0618 14:46:20.998270 11553 controller.go:246] "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-8a5tv3" "kubeadmControlPlane"="kcp-foo-8a5tv3" "namespace"="test" I0618 14:46:22.699593 11553 controller.go:331] "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-8a5tv3" "kubeadmControlPlane"="kcp-foo-8a5tv3" "namespace"="test" "needRollout"=["kcp-foo-8a5tv3-cswtp"] I0618 14:46:22.699755 11553 scale.go:212] "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-8a5tv3" "kubeadmControlPlane"="kcp-foo-8a5tv3" "namespace"="test" "failures"="[machine kcp-foo-8a5tv3-ns9jz does not have APIServerPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have ControllerManagerPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have SchedulerPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have EtcdPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have EtcdMemberHealthy condition]" --- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (1.70s) ... skipping 60 lines ... ================================== Random Seed: [1m1655563550[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: [1m1655563550[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 247 lines ... --- PASS: TestForwardEtcdLeadership/move_etcd_leader/returns_error_if_failed_to_move_to_the_leader_candidate (0.00s) --- PASS: TestForwardEtcdLeadership/move_etcd_leader/returns_error_if_the_leader_candidate_doesn't_exist_in_etcd (0.00s) === RUN TestReconcileEtcdMembers === RUN TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_and_removes_the_node_from_kubeadm_config_for_Kubernetes_version_<_1.22.0 === RUN TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_for_Kubernetes_version_>=_1.22.0 === RUN TestReconcileEtcdMembers/return_error_if_there_aren't_enough_control_plane_nodes --- FAIL: TestReconcileEtcdMembers (0.22s) --- PASS: TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_and_removes_the_node_from_kubeadm_config_for_Kubernetes_version_<_1.22.0 (0.14s) --- FAIL: TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_for_Kubernetes_version_>=_1.22.0 (0.03s) workload_cluster_etcd_test.go:608: Unexpected error: <errors.aggregate | len:2, cap:2>: [ { msg: "cluster has fewer than 2 control plane nodes; removing an etcd member is not supported", stack: [0x1740e76, 0x43f42a, 0x43f3f7, 0x432e62, 0x461351], }, { ... skipping 47 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 E0618 14:46:05.897211 11495 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" E0618 14:46:14.220299 11495 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" E0618 14:46:23.211454 11495 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" E0618 14:46:34.341762 11495 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" E0618 14:46:50.814928 11495 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" E0618 14:47:03.823501 11495 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" E0618 14:47:21.470860 11495 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" E0618 14:47:42.394238 11495 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" E0618 14:48:13.410718 11495 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" E0618 14:48:58.567999 11495 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 82 lines ... --- PASS: TestIsKubernetesVersionSupported (0.00s) --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_<_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s) FAIL I0618 14:48:58.578000 11495 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" FAIL sigs.k8s.io/cluster-api/controlplane/kubeadm/internal 187.951s === RUN TestEtcdMembers_WithErrors --- PASS: TestEtcdMembers_WithErrors (0.00s) === RUN TestEtcdMembers_WithSuccess --- PASS: TestEtcdMembers_WithSuccess (0.00s) PASS ok sigs.k8s.io/cluster-api/controlplane/kubeadm/internal/etcd 0.091s ... skipping 286 lines ... I0618 14:46:12.724737 11859 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" I0618 14:46:12.824770 11859 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}} I0618 14:46:12.925167 11859 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" I0618 14:46:12.925243 11859 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1 I0618 14:46:12.925946 11859 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1 I0618 14:46:13.061627 11859 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-3texwt"} E0618 14:46:13.122051 11859 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•[0mI0618 14:46:14.200995 11859 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-t2nvg8"} E0618 14:46:14.231080 11859 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•[0mE0618 14:46:15.354815 11859 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" E0618 14:46:16.373698 11859 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•[0mE0618 14:46:17.537217 11859 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•[0mE0618 14:46:18.568466 11859 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" E0618 14:46:19.603930 11859 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•[0mI0618 14:46:19.607401 11859 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" I0618 14:46:19.607454 11859 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" I0618 14:46:19.607530 11859 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 5 of 5 Specs in 20.149 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (20.15s) PASS ok sigs.k8s.io/cluster-api/exp/addons/controllers 20.233s ? 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.01s) === 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 E0618 14:46:05.531808 12025 machinepool_controller_phases.go:237] "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" === RUN TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused --- PASS: TestReconcileMachinePoolInfrastructure (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s) === RUN TestMachinePoolFinalizer ... skipping 96 lines ... I0618 14:46:16.811348 12025 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI0618 14:46:16.849310 12025 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0m[32m•[0mI0618 14:46:16.851136 12025 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 9 of 9 Specs in 11.307 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m9 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (11.31s) PASS ok sigs.k8s.io/cluster-api/exp/controllers 11.619s ? 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 204 lines ... I0618 14:46:40.614177 15005 server.go:199] controller-runtime/webhook "msg"="serving webhook server" "host"="" "port"=43335 I0618 14:46:40.616123 15005 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0mI0618 14:46:41.616080 15005 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 14 of 14 Specs in 8.243 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m14 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestPatch (8.24s) === 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) ... skipping 105 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.034s FAIL make: *** [Makefile:116: test] Error 1