This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2022-08-15 03:06
Elapsed4m24s
Revisionrelease-0.3

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0815 03:07:50.238828    8383 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0815 03:07:50.837795    8383 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" 
•I0815 03:07:50.850556    8383 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 15.235 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (15.24s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	45.692s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 316 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1399 lines ...
I0815 03:07:37.522360   10535 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0815 03:07:37.522387   10535 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0815 03:07:37.522420   10535 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0815 03:07:37.522916   10535 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0815 03:07:37.526652   10535 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
=== RUN   TestClusterReconcilePhases
2022/08/15 03:07:37 http: TLS handshake error from 127.0.0.1:34724: EOF
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0815 03:07:37.619606   10535 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"
I0815 03:07:37.622471   10535 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infra_config_is_marked_for_deletion
... skipping 104 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0815 03:07:37.656546   10535 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
I0815 03:07:37.659253   10535 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"
E0815 03:07:37.659733   10535 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
I0815 03:07:37.660386   10535 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.01s)
    --- 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.01s)
=== RUN   TestWatches
I0815 03:07:37.997074   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0815 03:07:37.999335   10535 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0815 03:07:38.005330   10535 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0815 03:07:38.005411   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0815 03:07:38.120826   10535 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0815 03:07:38.120904   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0815 03:07:38.221315   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv" "noderef"="node-1"
E0815 03:07:38.227973   10535 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0815 03:07:38.228023   10535 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0815 03:07:38.256593   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv" "noderef"="node-1"
E0815 03:07:38.278876   10535 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-j6r2l\" in namespace \"test-machine-watches-6sndv\", requeuing: requeue in 1s"  
E0815 03:07:38.290653   10535 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-j6r2l\" in namespace \"test-machine-watches-6sndv\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-j6r2l\" in namespace \"test-machine-watches-6sndv\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv"
--- PASS: TestWatches (0.65s)
=== 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
I0815 03:07:38.509423   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-8s97z" "namespace"="test-machine-watches-6sndv" "count"=1
I0815 03:07:38.509493   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-8s97z" "namespace"="test-machine-watches-6sndv" "descendants"="Worker machines: machine-created-j6r2l" "indirect descendants count"=0
I0815 03:07:38.523638   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-8s97z" "namespace"="test-machine-watches-6sndv" "count"=1
I0815 03:07:38.523700   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-8s97z" "namespace"="test-machine-watches-6sndv" "descendants"="Worker machines: machine-created-j6r2l" "indirect descendants count"=0
I0815 03:07:39.291316   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-8s97z" "machine"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"f606636d-3c62-4513-a834-91c20dcc75a9","apiVersion":"v1"}
E0815 03:07:39.344245   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-j6r2l\" not found" "controller"="machine" "name"="machine-created-j6r2l" "namespace"="test-machine-watches-6sndv"
E0815 03:07:40.465275   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-mg64l\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-kzgdm\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-kzgdm: secrets \"machine-reconcile-kzgdm-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-mg64l" "namespace"="default"
I0815 03:07:41.465957   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-kzgdm" "machine"="machine-created-mg64l" "namespace"="default" "cause"="noderef is nil" "node"=null
I0815 03:07:41.497097   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-kzgdm" "machine"="machine-created-mg64l" "namespace"="default" "cause"="noderef is nil" "node"=null
I0815 03:07:41.517819   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-kzgdm" "machine"="machine-created-mg64l" "namespace"="default" "cause"="noderef is nil" "node"=null
E0815 03:07:41.547859   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-mg64l\" not found" "controller"="machine" "name"="machine-created-mg64l" "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
I0815 03:07:41.563182   10535 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"
I0815 03:07:41.563342   10535 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
I0815 03:07:41.569668   10535 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"
I0815 03:07:41.569791   10535 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
E0815 03:07:41.571030   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-kzgdm\" not found" "controller"="cluster" "name"="machine-reconcile-kzgdm" "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/all_machines_are_running (0.00s)
    --- PASS: TestMachineDeploymentSyncStatus/scaling_up (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0815 03:07:41.704380   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b9bxc" "namespace"="test-mhc-5r4hf" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
E0815 03:07:41.754934   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-ff8wn\" not found"  "cluster"="test-mhc-5r4hf/test-cluster-ff8wn"
I0815 03:07:41.754996   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
=== 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
E0815 03:07:41.860447   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-b9bxc\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-b9bxc\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-b9bxc" "namespace"="test-mhc-5r4hf"
I0815 03:07:42.860755   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2gg6q" "namespace"="test-mhc-5jbp8" 
I0815 03:07:42.860882   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sm7qx" "namespace"="test-mhc-8rmbn" 
I0815 03:07:42.860913   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5v5bv" "namespace"="test-mhc-kg48s" 
I0815 03:07:42.880895   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 03:07:43.009970   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b9bxc" "namespace"="test-mhc-5r4hf" 
I0815 03:07:43.010043   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5v5bv" "namespace"="test-mhc-kg48s" 
I0815 03:07:43.015945   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5v5bv" "namespace"="test-mhc-kg48s" 
I0815 03:07:43.058687   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5v5bv" "namespace"="test-mhc-kg48s" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
E0815 03:07:43.064943   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-kg48s/test-cluster-vqwqt"
E0815 03:07:43.066858   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-vqwqt\" not found" "controller"="cluster" "name"="test-cluster-vqwqt" "namespace"="test-mhc-kg48s"
I0815 03:07:43.186578   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xtxq5" "namespace"="test-mhc-fjzjq" 
I0815 03:07:43.208436   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 03:07:43.339629   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xtxq5" "namespace"="test-mhc-fjzjq" 
E0815 03:07:43.391925   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-fjzjq/test-cluster-tqkq6"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0815 03:07:43.397457   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xtxq5" "namespace"="test-mhc-fjzjq" 
I0815 03:07:43.517943   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
inframachine created: test-mhc-machine-infra-rrftn
I0815 03:07:43.533124   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-pbg2t
I0815 03:07:43.566702   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:43.567090   10535 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-2n24f/test-mhc-b8rbj/test-mhc-machine-pbg2t/"
E0815 03:07:43.640766   10535 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-k2sjd"
node created: test-mhc-node-k2sjd
E0815 03:07:43.641066   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k2sjd, got []"  "node"="test-mhc-node-k2sjd"
inframachine created: test-mhc-machine-infra-5zfdh
machine created: test-mhc-machine-fdn2s
E0815 03:07:43.771352   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-knvsc, got []"  "node"="test-mhc-node-knvsc"
E0815 03:07:43.771625   10535 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-knvsc"
node created: test-mhc-node-knvsc
I0815 03:07:43.778052   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:43.778539   10535 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-2n24f/test-mhc-b8rbj/test-mhc-machine-fdn2s/"
I0815 03:07:43.940165   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:43.969068   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
Cleaning up nodes, machines and infra machines.
I0815 03:07:43.979217   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:43.979932   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-2n24f/test-mhc-b8rbj/test-mhc-machine-pbg2t/"
I0815 03:07:44.003412   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:44.004039   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-2n24f/test-mhc-b8rbj/test-mhc-machine-pbg2t/"
I0815 03:07:44.010608   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:44.011300   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-2n24f/test-mhc-b8rbj/test-mhc-machine-pbg2t/"
I0815 03:07:44.011920   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-2n24f/test-mhc-b8rbj/test-mhc-machine-fdn2s/"
E0815 03:07:44.116820   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-pbg2t\" in namespace \"test-mhc-2n24f\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-pbg2t" "namespace"="test-mhc-2n24f"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0815 03:07:44.158679   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-6sndv/machine-reconcile-8s97z"
I0815 03:07:44.161357   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-dv854" "namespace"="test-mhc-2n24f" "count"=2
I0815 03:07:44.161459   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dv854" "namespace"="test-mhc-2n24f" "descendants"="Worker machines: test-mhc-machine-pbg2t,test-mhc-machine-fdn2s" "indirect descendants count"=0
inframachine created: test-mhc-machine-infra-w4cm9
I0815 03:07:44.186054   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-dv854" "namespace"="test-mhc-2n24f" "count"=2
I0815 03:07:44.186120   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dv854" "namespace"="test-mhc-2n24f" "descendants"="Worker machines: test-mhc-machine-pbg2t,test-mhc-machine-fdn2s" "indirect descendants count"=0
machine created: test-mhc-machine-9q96t
E0815 03:07:44.263389   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-b8rbj\" not found" "controller"="machinehealthcheck" "name"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f"
I0815 03:07:45.117438   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-dv854" "machine"="test-mhc-machine-fdn2s" "namespace"="test-mhc-2n24f" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-knvsc"}
E0815 03:07:45.178964   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fdn2s\" not found" "controller"="machine" "name"="test-mhc-machine-fdn2s" "namespace"="test-mhc-2n24f"
I0815 03:07:45.263731   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:45.283204   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 03:07:45.333962   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b8rbj" "namespace"="test-mhc-2n24f" 
I0815 03:07:45.334031   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:45.335773   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:45.337582   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
... skipping 394 lines ...
I0815 03:07:46.227032   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.228757   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.231320   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.233724   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.239661   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.244861   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
E0815 03:07:46.245577   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-pbg2t\" not found" "controller"="machine" "name"="test-mhc-machine-pbg2t" "namespace"="test-mhc-2n24f"
I0815 03:07:46.246556   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.248227   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.250060   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.251683   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.253454   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:46.255044   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
... skipping 457 lines ...
I0815 03:07:47.262086   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.263030   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.263787   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.265508   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.267252   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.268943   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.269145   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.280533   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.280835   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.289716   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.290109   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.303080   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.303530   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.311339   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.311702   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
E0815 03:07:47.327877   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2ptwm, got []"  "node"="test-mhc-node-2ptwm"
E0815 03:07:47.328159   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2ptwm, got []"  "node"="test-mhc-node-2ptwm"
node created: test-mhc-node-2ptwm
I0815 03:07:47.329034   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.329379   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.336447   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.336731   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.359458   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.362607   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-9q96t" "namespace"="test-mhc-fg9j9" "noderef"="test-mhc-node-2ptwm"
inframachine created: test-mhc-machine-infra-kwv8g
I0815 03:07:47.383058   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
machine created: test-mhc-machine-p66pc
I0815 03:07:47.386441   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.395626   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.401467   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.411313   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.411859   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-p66pc/"
I0815 03:07:47.427546   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.427910   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-p66pc/"
I0815 03:07:47.487138   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.487597   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-p66pc/"
E0815 03:07:47.490510   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-vqqsb, got []"  "node"="test-mhc-node-vqqsb"
E0815 03:07:47.490734   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-vqqsb, got []"  "node"="test-mhc-node-vqqsb"
node created: test-mhc-node-vqqsb
I0815 03:07:47.509935   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
inframachine created: test-mhc-machine-infra-d5ljw
machine created: test-mhc-machine-8lbg9
I0815 03:07:47.532423   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.543482   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
... skipping 2 lines ...
I0815 03:07:47.554447   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.556354   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.558095   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.561006   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.562701   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.565794   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.568091   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
I0815 03:07:47.596834   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.598139   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
I0815 03:07:47.605541   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.606086   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
I0815 03:07:47.608871   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.609485   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
node created: test-mhc-node-drp44
E0815 03:07:47.633170   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-drp44, got []"  "node"="test-mhc-node-drp44"
E0815 03:07:47.635223   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-drp44, got []"  "node"="test-mhc-node-drp44"
I0815 03:07:47.635730   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.636290   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
I0815 03:07:47.648982   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.649578   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
I0815 03:07:47.656116   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.656701   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
Cleaning up nodes, machines and infra machines.
I0815 03:07:47.660955   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.662359   10535 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-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/test-mhc-node-drp44"
I0815 03:07:47.683165   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.685982   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
Cleaning up nodes, machines and infra machines.
I0815 03:07:47.706705   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:47.707732   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fg9j9/test-mhc-mxjvp/test-mhc-machine-9q96t/"
I0815 03:07:47.747543   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-n4z4h" "namespace"="test-mhc-fg9j9" "count"=3
I0815 03:07:47.747642   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-n4z4h" "namespace"="test-mhc-fg9j9" "descendants"="Worker machines: test-mhc-machine-9q96t,test-mhc-machine-p66pc,test-mhc-machine-8lbg9" "indirect descendants count"=0
I0815 03:07:47.758436   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-n4z4h" "namespace"="test-mhc-fg9j9" "count"=3
I0815 03:07:47.758499   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-n4z4h" "namespace"="test-mhc-fg9j9" "descendants"="Worker machines: test-mhc-machine-p66pc,test-mhc-machine-8lbg9,test-mhc-machine-9q96t" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
E0815 03:07:47.824143   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-8lbg9\" in namespace \"test-mhc-fg9j9\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-8lbg9" "namespace"="test-mhc-fg9j9"
inframachine created: test-mhc-machine-infra-sfclz
I0815 03:07:47.847098   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fg9j9/test-mhc-mxjvp/test-mhc-machine-8lbg9/"
E0815 03:07:47.852172   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-mxjvp\" not found" "controller"="machinehealthcheck" "name"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9"
machine created: test-mhc-machine-td4zr
I0815 03:07:48.831171   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-n4z4h" "machine"="test-mhc-machine-9q96t" "namespace"="test-mhc-fg9j9" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-2ptwm","uid":"818f5100-b62d-4f75-83f6-e4f09d13fa5b","apiVersion":"v1"}
I0815 03:07:48.852598   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:48.876679   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0815 03:07:48.893366   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9q96t\" not found" "controller"="machine" "name"="test-mhc-machine-9q96t" "namespace"="test-mhc-fg9j9"
I0815 03:07:48.900244   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mxjvp" "namespace"="test-mhc-fg9j9" 
I0815 03:07:48.900313   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:48.905390   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:48.926383   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:48.967673   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:49.048884   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
E0815 03:07:49.184693   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-2n24f/test-cluster-dv854"
I0815 03:07:49.209932   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:49.533941   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:49.893930   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-n4z4h" "machine"="test-mhc-machine-p66pc" "namespace"="test-mhc-fg9j9" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-vqqsb"}
E0815 03:07:49.935211   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-p66pc\" not found" "controller"="machine" "name"="test-mhc-machine-p66pc" "namespace"="test-mhc-fg9j9"
I0815 03:07:50.174885   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:50.935788   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-n4z4h" "machine"="test-mhc-machine-8lbg9" "namespace"="test-mhc-fg9j9" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-drp44"}
E0815 03:07:50.997266   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-8lbg9\" not found" "controller"="machine" "name"="test-mhc-machine-8lbg9" "namespace"="test-mhc-fg9j9"
I0815 03:07:51.455933   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.005294   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.012375   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.037037   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.043148   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.052866   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.064206   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.073125   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
E0815 03:07:52.091189   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2n6nj, got []"  "node"="test-mhc-node-2n6nj"
node created: test-mhc-node-2n6nj
E0815 03:07:52.091394   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2n6nj, got []"  "node"="test-mhc-node-2n6nj"
I0815 03:07:52.116509   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-td4zr" "namespace"="test-mhc-zcmq4" "noderef"="test-mhc-node-2n6nj"
I0815 03:07:52.118082   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
inframachine created: test-mhc-machine-infra-8589v
machine created: test-mhc-machine-c7bbd
I0815 03:07:52.143902   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.154541   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
... skipping 3 lines ...
I0815 03:07:52.259288   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.266480   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.275726   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.283125   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.308637   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.329164   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
E0815 03:07:52.339423   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97hn6, got []"  "node"="test-mhc-node-97hn6"
E0815 03:07:52.339557   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97hn6, got []"  "node"="test-mhc-node-97hn6"
node created: test-mhc-node-97hn6
I0815 03:07:52.344778   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.346837   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.353264   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
inframachine created: test-mhc-machine-infra-7kpjz
I0815 03:07:52.357502   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-c7bbd" "namespace"="test-mhc-zcmq4" "noderef"="test-mhc-node-97hn6"
machine created: test-mhc-machine-vkdlx
node created: test-mhc-node-ws7dk
E0815 03:07:52.471180   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ws7dk, got []"  "node"="test-mhc-node-ws7dk"
E0815 03:07:52.471392   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ws7dk, got []"  "node"="test-mhc-node-ws7dk"
I0815 03:07:52.547823   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.572568   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.590483   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.596497   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
Cleaning up nodes, machines and infra machines.
I0815 03:07:52.602078   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.619690   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
Cleaning up nodes, machines and infra machines.
E0815 03:07:52.653744   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-c7bbd\" in namespace \"test-mhc-zcmq4\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-c7bbd" "namespace"="test-mhc-zcmq4"
I0815 03:07:52.674267   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-p82mn" "namespace"="test-mhc-zcmq4" "count"=3
I0815 03:07:52.674352   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p82mn" "namespace"="test-mhc-zcmq4" "descendants"="Worker machines: test-mhc-machine-c7bbd,test-mhc-machine-vkdlx,test-mhc-machine-td4zr" "indirect descendants count"=0
I0815 03:07:52.678906   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-p82mn" "namespace"="test-mhc-zcmq4" "count"=3
I0815 03:07:52.678974   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p82mn" "namespace"="test-mhc-zcmq4" "descendants"="Worker machines: test-mhc-machine-td4zr,test-mhc-machine-c7bbd,test-mhc-machine-vkdlx" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
inframachine created: test-mhc-machine-infra-7t27k
machine created: test-mhc-machine-vksn7
I0815 03:07:52.744683   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:52.756263   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 03:07:52.778406   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:52.778476   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
E0815 03:07:52.780027   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-fg9j9/test-cluster-n4z4h"
I0815 03:07:52.782686   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:53.588871   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vqjsl" "namespace"="test-mhc-zcmq4" 
I0815 03:07:53.654304   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-p82mn" "machine"="test-mhc-machine-vkdlx" "namespace"="test-mhc-zcmq4" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-ws7dk"}
E0815 03:07:53.712884   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vkdlx\" not found" "controller"="machine" "name"="test-mhc-machine-vkdlx" "namespace"="test-mhc-zcmq4"
I0815 03:07:54.713480   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-p82mn" "machine"="test-mhc-machine-c7bbd" "namespace"="test-mhc-zcmq4" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-97hn6","uid":"0997d2cf-533a-42a0-84f5-940c311ffde3","apiVersion":"v1"}
E0815 03:07:54.767943   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-c7bbd\" not found" "controller"="machine" "name"="test-mhc-machine-c7bbd" "namespace"="test-mhc-zcmq4"
I0815 03:07:55.768519   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-p82mn" "machine"="test-mhc-machine-td4zr" "namespace"="test-mhc-zcmq4" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-2n6nj","uid":"eb3ef5a2-edc7-4679-b137-b301605d95aa","apiVersion":"v1"}
E0815 03:07:55.810206   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-td4zr\" not found" "controller"="machine" "name"="test-mhc-machine-td4zr" "namespace"="test-mhc-zcmq4"
I0815 03:07:56.820838   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:56.828216   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:56.842923   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:56.856187   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
E0815 03:07:56.857349   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7m9wq, got []"  "node"="test-mhc-node-7m9wq"
node created: test-mhc-node-7m9wq
E0815 03:07:56.857563   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7m9wq, got []"  "node"="test-mhc-node-7m9wq"
I0815 03:07:56.858497   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:56.864356   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-vksn7" "namespace"="test-mhc-7h9ls" "noderef"="test-mhc-node-7m9wq"
E0815 03:07:56.867803   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7m9wq, got []"  "node"="test-mhc-node-7m9wq"
E0815 03:07:56.867854   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7m9wq, got []"  "node"="test-mhc-node-7m9wq"
E0815 03:07:56.868592   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7m9wq, got []"  "node"="test-mhc-node-7m9wq"
E0815 03:07:56.868629   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7m9wq, got []"  "node"="test-mhc-node-7m9wq"
I0815 03:07:56.879038   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:56.881270   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
inframachine created: test-mhc-machine-infra-h95rl
machine created: test-mhc-machine-hv8lx
E0815 03:07:57.012514   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4wzkj, got []"  "node"="test-mhc-node-4wzkj"
node created: test-mhc-node-4wzkj
E0815 03:07:57.013171   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4wzkj, got []"  "node"="test-mhc-node-4wzkj"
inframachine created: test-mhc-machine-infra-cmwtl
machine created: test-mhc-machine-wg92h
I0815 03:07:57.059601   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.265845   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
Cleaning up nodes, machines and infra machines.
I0815 03:07:57.278045   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.278187   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-cthpm" "machine"="test-mhc-machine-wg92h" "namespace"="test-mhc-7h9ls" "cause"="noderef is nil" "node"=null
I0815 03:07:57.284655   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
Cleaning up nodes, machines and infra machines.
I0815 03:07:57.294588   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.296860   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.297440   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-vksn7/"
I0815 03:07:57.322878   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.323530   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-vksn7/"
I0815 03:07:57.323954   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-hv8lx/"
E0815 03:07:57.354645   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-wg92h\" not found" "controller"="machine" "name"="test-mhc-machine-wg92h" "namespace"="test-mhc-7h9ls"
I0815 03:07:57.358861   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.359425   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-vksn7/"
I0815 03:07:57.359908   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-hv8lx/"
I0815 03:07:57.365937   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
I0815 03:07:57.366876   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-vksn7/"
I0815 03:07:57.367386   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7h9ls/test-mhc-4ng6n/test-mhc-machine-hv8lx/"
I0815 03:07:57.370192   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-cthpm" "namespace"="test-mhc-7h9ls" "count"=2
I0815 03:07:57.370262   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-cthpm" "namespace"="test-mhc-7h9ls" "descendants"="Worker machines: test-mhc-machine-hv8lx,test-mhc-machine-vksn7" "indirect descendants count"=0
I0815 03:07:57.374910   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-cthpm" "namespace"="test-mhc-7h9ls" "count"=2
I0815 03:07:57.374964   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-cthpm" "namespace"="test-mhc-7h9ls" "descendants"="Worker machines: test-mhc-machine-vksn7,test-mhc-machine-hv8lx" "indirect descendants count"=0
I0815 03:07:57.387945   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4ng6n" "namespace"="test-mhc-7h9ls" 
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_longer_than_the_NodeStartupTimeout
... skipping 56 lines ...
I0815 03:07:57.674467   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.676159   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.677833   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.686888   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.688675   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.690432   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
E0815 03:07:57.691248   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-zcmq4/test-cluster-p82mn"
I0815 03:07:57.692155   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.693840   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.695531   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.697162   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.698849   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:57.700563   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
... skipping 309 lines ...
I0815 03:07:58.404486   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.406193   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.408255   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.409942   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.411677   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.413545   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
E0815 03:07:58.415988   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vksn7\" not found" "controller"="machine" "name"="test-mhc-machine-vksn7" "namespace"="test-mhc-7h9ls"
I0815 03:07:58.418901   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.420678   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.422471   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.424208   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.425922   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:58.430859   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
... skipping 490 lines ...
I0815 03:07:59.456448   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.458157   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.459983   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.461860   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.463538   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.465193   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
E0815 03:07:59.466084   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hv8lx\" not found" "controller"="machine" "name"="test-mhc-machine-hv8lx" "namespace"="test-mhc-7h9ls"
I0815 03:07:59.466809   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.468486   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.470257   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.472030   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.473671   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:07:59.475325   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
... skipping 432 lines ...
I0815 03:08:00.470695   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.472417   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.475373   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.475966   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.477102   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.480138   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.480380   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.490971   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.491254   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.510168   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.510529   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.523418   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.523757   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.534192   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.534523   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.545787   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.546154   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.551784   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.552142   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
node created: test-mhc-node-46f2g
E0815 03:08:00.556862   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-46f2g, got []"  "node"="test-mhc-node-46f2g"
E0815 03:08:00.556945   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-46f2g, got []"  "node"="test-mhc-node-46f2g"
I0815 03:08:00.558101   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-4qq29" "namespace"="test-mhc-8w2l5" "noderef"="test-mhc-node-46f2g"
E0815 03:08:00.562244   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-46f2g, got []"  "node"="test-mhc-node-46f2g"
E0815 03:08:00.562265   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-46f2g, got []"  "node"="test-mhc-node-46f2g"
E0815 03:08:00.562294   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-46f2g, got []"  "node"="test-mhc-node-46f2g"
E0815 03:08:00.562299   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-46f2g, got []"  "node"="test-mhc-node-46f2g"
I0815 03:08:00.564803   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.583953   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.591231   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.591517   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/test-mhc-node-46f2g"
I0815 03:08:00.615452   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.615906   10535 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-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/test-mhc-node-46f2g"
Cleaning up nodes, machines and infra machines.
I0815 03:08:00.625373   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.625707   10535 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-8w2l5/test-mhc-tcrnz/test-mhc-machine-4qq29/"
I0815 03:08:00.641228   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nxtlz" "namespace"="test-mhc-8w2l5" "count"=1
I0815 03:08:00.641306   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nxtlz" "namespace"="test-mhc-8w2l5" "descendants"="Worker machines: test-mhc-machine-4qq29" "indirect descendants count"=0
I0815 03:08:00.645178   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nxtlz" "namespace"="test-mhc-8w2l5" "count"=1
I0815 03:08:00.645229   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nxtlz" "namespace"="test-mhc-8w2l5" "descendants"="Worker machines: test-mhc-machine-4qq29" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0815 03:08:00.728173   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nxtlz" "machine"="test-mhc-machine-4qq29" "namespace"="test-mhc-8w2l5" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-46f2g"}
I0815 03:08:00.731526   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" "creating"=1 "need"=1
I0815 03:08:00.731569   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:00.741308   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-dr4zv-s5t5q\"" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:00.813250   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcrnz" "namespace"="test-mhc-8w2l5" 
I0815 03:08:00.818834   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:00.849965   10535 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:00.856238   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0815 03:08:00.920917   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-4qq29\" not found" "controller"="machine" "name"="test-mhc-machine-4qq29" "namespace"="test-mhc-8w2l5"
I0815 03:08:00.973556   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.930344   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.931240   10535 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.936922   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.937750   10535 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.959183   10535 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
... skipping 4 lines ...
I0815 03:08:01.981894   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.982226   10535 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.989770   10535 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.989824   10535 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.995101   10535 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:01.995157   10535 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
E0815 03:08:02.390642   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-7h9ls/test-cluster-cthpm"
I0815 03:08:02.987480   10535 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:02.987528   10535 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.000578   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.001177   10535 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-kpwqt/test-mhc-d6gbh/mhc-ms-dr4zv-s5t5q/"
I0815 03:08:03.009156   10535 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.013734   10535 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.013780   10535 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.013883   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.014221   10535 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-kpwqt/test-mhc-d6gbh/mhc-ms-dr4zv-s5t5q/"
I0815 03:08:03.019746   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.020043   10535 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-kpwqt/test-mhc-d6gbh/mhc-ms-dr4zv-s5t5q/"
I0815 03:08:03.020343   10535 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.032829   10535 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.032866   10535 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.081379   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-kn5qr" "namespace"="test-mhc-kpwqt" "count"=1
I0815 03:08:03.081436   10535 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-kn5qr" "namespace"="test-mhc-kpwqt" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-dr4zv"
I0815 03:08:03.085417   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d6gbh" "namespace"="test-mhc-kpwqt" 
I0815 03:08:03.086181   10535 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" "machine"="mhc-ms-dr4zv-s5t5q"
I0815 03:08:03.086731   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-kn5qr" "namespace"="test-mhc-kpwqt" "descendants"="Machine sets: mhc-ms-dr4zv;Worker machines: mhc-ms-dr4zv-s5t5q" "indirect descendants count"=1
I0815 03:08:03.091236   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-kn5qr" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" "cause"="cluster is being deleted" "node"=null
I0815 03:08:03.095183   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-kn5qr" "namespace"="test-mhc-kpwqt" "descendants"="Worker machines: mhc-ms-dr4zv-s5t5q" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_a_machine_is_paused
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created
E0815 03:08:03.098615   10535 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-dr4zv\" not found" "machineset"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt" 
E0815 03:08:03.098680   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-dr4zv\" not found" "controller"="machineset" "name"="mhc-ms-dr4zv" "namespace"="test-mhc-kpwqt"
I0815 03:08:03.277807   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-kn5qr" "machine"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt" "cause"="cluster is being deleted" "node"=null
I0815 03:08:03.347186   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
E0815 03:08:03.349002   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-dr4zv-s5t5q\" not found" "controller"="machine" "name"="mhc-ms-dr4zv-s5t5q" "namespace"="test-mhc-kpwqt"
inframachine created: test-mhc-machine-infra-qwx46
I0815 03:08:03.366905   10535 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-hsb5f
I0815 03:08:03.493403   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:03.499596   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:03.500679   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
... skipping 425 lines ...
I0815 03:08:04.359708   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.361394   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.363086   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.364815   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.366595   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
node created: test-mhc-node-4cvtg
E0815 03:08:04.378877   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4cvtg, got []"  "node"="test-mhc-node-4cvtg"
E0815 03:08:04.379048   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4cvtg, got []"  "node"="test-mhc-node-4cvtg"
E0815 03:08:04.379087   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4cvtg, got []"  "node"="test-mhc-node-4cvtg"
I0815 03:08:04.445468   10535 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-hsb5f" "target"="test-mhc-bdnx7/test-mhc-xprd4/test-mhc-machine-hsb5f/"
I0815 03:08:04.460774   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.502321   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.519595   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.522585   10535 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-hsb5f" "target"="test-mhc-bdnx7/test-mhc-xprd4/test-mhc-machine-hsb5f/test-mhc-node-4cvtg"
I0815 03:08:04.548765   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.553190   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
Cleaning up nodes, machines and infra machines.
I0815 03:08:04.557752   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.561225   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.564935   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.572679   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
I0815 03:08:04.575149   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-s4255" "namespace"="test-mhc-bdnx7" "count"=1
I0815 03:08:04.575225   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-s4255" "namespace"="test-mhc-bdnx7" "descendants"="Worker machines: test-mhc-machine-hsb5f" "indirect descendants count"=0
E0815 03:08:04.580053   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-hsb5f\" in namespace \"test-mhc-bdnx7\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-hsb5f" "namespace"="test-mhc-bdnx7"
I0815 03:08:04.581632   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-s4255" "namespace"="test-mhc-bdnx7" "count"=1
I0815 03:08:04.581676   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-s4255" "namespace"="test-mhc-bdnx7" "descendants"="Worker machines: test-mhc-machine-hsb5f" "indirect descendants count"=0
I0815 03:08:04.585836   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xprd4" "namespace"="test-mhc-bdnx7" 
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted
I0815 03:08:04.711576   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
inframachine created: test-mhc-machine-infra-5ltbq
... skipping 385 lines ...
I0815 03:08:05.634331   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.636334   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.638104   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.639938   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.641544   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.643432   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
E0815 03:08:05.644807   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hsb5f\" not found" "controller"="machine" "name"="test-mhc-machine-hsb5f" "namespace"="test-mhc-bdnx7"
I0815 03:08:05.645261   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.647002   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.649391   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.651248   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.653654   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.655598   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.658031   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
E0815 03:08:05.659841   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-8w2l5/test-cluster-nxtlz"
I0815 03:08:05.660026   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.662006   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.663860   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.665767   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.667651   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:05.669594   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
... skipping 433 lines ...
I0815 03:08:06.648335   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.650081   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.652026   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.662009   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.663987   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.667048   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
E0815 03:08:06.681847   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q2fcs, got []"  "node"="test-mhc-node-q2fcs"
E0815 03:08:06.681856   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q2fcs, got []"  "node"="test-mhc-node-q2fcs"
E0815 03:08:06.681847   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q2fcs, got []"  "node"="test-mhc-node-q2fcs"
node created: test-mhc-node-q2fcs
I0815 03:08:06.688125   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-p654z" "namespace"="test-mhc-6q6xj" "noderef"="test-mhc-node-q2fcs"
I0815 03:08:06.696089   10535 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-p654z" "target"="test-mhc-6q6xj/test-mhc-9626w/test-mhc-machine-p654z/"
I0815 03:08:06.707942   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.738314   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.748711   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.754596   10535 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-p654z" "target"="test-mhc-6q6xj/test-mhc-9626w/test-mhc-machine-p654z/test-mhc-node-q2fcs"
I0815 03:08:06.774292   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.786217   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.809411   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
Cleaning up nodes, machines and infra machines.
I0815 03:08:06.826368   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
I0815 03:08:06.832997   10535 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-p654z" "target"="test-mhc-6q6xj/test-mhc-9626w/test-mhc-machine-p654z/"
I0815 03:08:06.841033   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-sjs6x" "namespace"="test-mhc-6q6xj" "descendants"="Worker machines: test-mhc-machine-p654z" "indirect descendants count"=1
I0815 03:08:06.846797   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-sjs6x" "namespace"="test-mhc-6q6xj" "descendants"="Worker machines: test-mhc-machine-p654z" "indirect descendants count"=1
E0815 03:08:06.851477   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-9626w\" not found" "controller"="machinehealthcheck" "name"="test-mhc-9626w" "namespace"="test-mhc-6q6xj"
--- PASS: TestMachineHealthCheck_Reconcile (25.18s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.05s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.05s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.04s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (1.25s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.34s)
... skipping 10 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (1.49s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.27s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0815 03:08:06.859918   10535 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
E0815 03:08:06.861760   10535 machinehealthcheck_controller.go:445]  "msg"="expected a Machine" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace
--- PASS: TestMachineToMachineHealthCheck (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace (0.00s)
=== RUN   TestNodeToMachineHealthCheck
=== RUN   TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node
E0815 03:08:06.864138   10535 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0815 03:08:06.864518   10535 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
E0815 03:08:06.865199   10535 machinehealthcheck_controller.go:480]  "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node node1, got [machine1 machine2]"  "node"="node1"
=== RUN   TestNodeToMachineHealthCheck/when_no_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_two_MachineHealthChecks_exist_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node,_but_not_in_the_Machine's_cluster
--- PASS: TestNodeToMachineHealthCheck (0.00s)
    --- PASS: TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node (0.00s)
... skipping 31 lines ...
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_nil (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_not_an_int_or_percentage (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_an_int (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_40%_(of_5) (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_60%_(of_7) (0.00s)
=== RUN   TestPatchTargets
I0815 03:08:06.870290   10535 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0815 03:08:06.871077   10535 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0815 03:08:06.873201   10535 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.01s)
=== 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
E0815 03:08:06.885832   10535 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
E0815 03:08:06.888549   10535 machineset_controller.go:569]  "msg"="Unable to convert selector" "error"="\"bad-operator\" is not a valid pod selector operator" "machine"="match" "machineset"="" "namespace"="" 
--- PASS: TestHasMatchingLabels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_empty_selector (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_bad_selector (0.00s)
=== RUN   TestMachineToDelete
... skipping 58 lines ...
Running Suite: Controllers Suite
================================
Random Seed: 1660532845
Will run 16 of 16 specs

I0815 03:08:06.930849   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-sjs6x" "machine"="test-mhc-machine-p654z" "namespace"="test-mhc-6q6xj" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-q2fcs","uid":"61bf89f7-38cb-4c99-bb6d-9fdb8bfc664b","apiVersion":"v1"}
E0815 03:08:06.980996   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-p654z\" not found" "controller"="machine" "name"="test-mhc-machine-p654z" "namespace"="test-mhc-6q6xj"
I0815 03:08:07.044745   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-7dmqd" "namespace"="ms-test" "creating"=2 "need"=2
I0815 03:08:07.044800   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-7dmqd" "namespace"="ms-test" 
I0815 03:08:07.075476   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-7dmqd-lz88r\"" "machineset"="ms-7dmqd" "namespace"="ms-test" 
I0815 03:08:07.075548   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-7dmqd" "namespace"="ms-test" 
I0815 03:08:07.110823   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-7dmqd-fkw66\"" "machineset"="ms-7dmqd" "namespace"="ms-test" 
I0815 03:08:07.230166   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-7dmqd" "namespace"="ms-test" "creating"=1 "need"=2
I0815 03:08:07.230212   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-7dmqd" "namespace"="ms-test" 
I0815 03:08:07.253824   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-7dmqd-8w2wl\"" "machineset"="ms-7dmqd" "namespace"="ms-test" 
E0815 03:08:07.294221   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.294886   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.294995   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.398658   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.398767   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.398990   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.399029   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.399200   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.399245   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-8w2wl-8bzcw, got []"  "node"="ms-7dmqd-8w2wl-8bzcw"
E0815 03:08:07.436215   10535 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-7dmqd-8w2wl-8bzcw for machine ms-test/ms-7dmqd-8w2wl: the cache is not started, can not read objects" "machineset"="ms-7dmqd" "namespace"="ms-test" 
E0815 03:08:07.447165   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.447194   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.447300   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.551844   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.551890   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.551894   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.551920   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.551971   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
E0815 03:08:07.552013   10535 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-7dmqd-fkw66-ctc55, got []"  "node"="ms-7dmqd-fkw66-ctc55"
I0815 03:08:07.680476   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-7dmqd-8w2wl,ms-7dmqd-fkw66" "indirect descendants count"=2
•I0815 03:08:07.687641   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-7dmqd-8w2wl,ms-7dmqd-fkw66" "indirect descendants count"=2
•E0815 03:08:07.842013   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-gskqb\" not found" "controller"="cluster" "name"="test1-gskqb" "namespace"="default"
I0815 03:08:07.851734   10535 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9626w" "namespace"="test-mhc-6q6xj" 
E0815 03:08:08.868889   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-kpwqt/test-cluster-kn5qr"
•I0815 03:08:08.971636   10535 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-62td4" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0815 03:08:09.093653   10535 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-62td4" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0815 03:08:09.098838   10535 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-62td4" "namespace"="default"
E0815 03:08:10.123412   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
•E0815 03:08:11.136597   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-bdnx7/test-cluster-s4255"
E0815 03:08:11.159171   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-c8t2r\" not found" "controller"="cluster" "name"="test3-c8t2r" "namespace"="default"
E0815 03:08:12.159943   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
E0815 03:08:13.183390   10535 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-6q6xj/test-cluster-sjs6x"
E0815 03:08:13.184051   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
•I0815 03:08:14.184514   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-7dmqd-8w2wl,ms-7dmqd-fkw66" "indirect descendants count"=2
E0815 03:08:14.189187   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-8rdp5: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-8rdp5" "namespace"="default"
E0815 03:08:15.212005   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
•E0815 03:08:16.212788   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-8rdp5: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-8rdp5" "namespace"="default"
E0815 03:08:17.229270   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
I0815 03:08:17.323014   10535 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-tv47p" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0815 03:08:17.345904   10535 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-tv47p" "namespace"="default" 
E0815 03:08:17.368848   10535 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-tv47p" "namespace"="default"
E0815 03:08:18.230008   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-8rdp5: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-8rdp5" "namespace"="default"
I0815 03:08:18.396093   10535 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-tv47p" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0815 03:08:18.396334   10535 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-tv47p" "namespace"="default" "noderef"="id-node-1"
E0815 03:08:18.409438   10535 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-tv47p" "namespace"="default"
E0815 03:08:19.235289   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
•I0815 03:08:19.348187   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0815 03:08:19.348237   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.368955   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-rd8q8-6657c7fddb-s8vhm\"" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.369016   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.380017   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-rd8q8-6657c7fddb-9nl9m\"" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.410012   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-vg58l" "machine"="test6-tv47p" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"54daea7c-be2e-4212-8692-4742c281aa44","apiVersion":"v1"}
E0815 03:08:19.436300   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-tv47p\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-tv47p" "namespace"="default"
I0815 03:08:19.504569   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0815 03:08:19.504636   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.516100   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-rd8q8-6657c7fddb-hn6sm\"" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.516162   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.529455   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-rd8q8-6657c7fddb-qphzn\"" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.553239   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0815 03:08:19.553279   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.564148   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rd8q8-6657c7fddb-s8tpc\"" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" 
I0815 03:08:19.662086   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0815 03:08:19.662140   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
I0815 03:08:19.672324   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rd8q8-cdfc6fd6c-bc528\"" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
E0815 03:08:19.890032   10535 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-rd8q8-cdfc6fd6c-bc528-9v69x for machine md-test/md-rd8q8-cdfc6fd6c-bc528: the cache is not started, can not read objects" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
I0815 03:08:19.941554   10535 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0815 03:08:19.941593   10535 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0815 03:08:19.945904   10535 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "machine"="md-rd8q8-6657c7fddb-hn6sm"
I0815 03:08:20.060315   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0815 03:08:20.060364   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
I0815 03:08:20.072148   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rd8q8-cdfc6fd6c-whwmn\"" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
E0815 03:08:20.235918   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-8rdp5: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-8rdp5" "namespace"="default"
I0815 03:08:20.246321   10535 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0815 03:08:20.246375   10535 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0815 03:08:20.250814   10535 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "machine"="md-rd8q8-6657c7fddb-qphzn"
I0815 03:08:20.285301   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0815 03:08:20.285346   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
I0815 03:08:20.298929   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rd8q8-cdfc6fd6c-ntwc4\"" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" 
I0815 03:08:20.468490   10535 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-vg58l" "machine"="test6-tv47p" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"54daea7c-be2e-4212-8692-4742c281aa44","apiVersion":"v1"}
E0815 03:08:20.469513   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-tv47p\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-tv47p" "namespace"="default"
I0815 03:08:20.503703   10535 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0815 03:08:20.503748   10535 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0815 03:08:20.509028   10535 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rd8q8-6657c7fddb" "namespace"="md-test" "machine"="md-rd8q8-6657c7fddb-s8tpc"
I0815 03:08:20.621592   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0815 03:08:20.621663   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-rd8q8-74d45c49c5" "namespace"="md-test" 
I0815 03:08:20.632640   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rd8q8-74d45c49c5-t2fdp\"" "machineset"="md-rd8q8-74d45c49c5" "namespace"="md-test" 
... skipping 8 lines ...
I0815 03:08:21.219221   10535 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rd8q8-cdfc6fd6c" "namespace"="md-test" "machine"="md-rd8q8-cdfc6fd6c-bc528"
I0815 03:08:21.236522   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-7dmqd-8w2wl,ms-7dmqd-fkw66" "indirect descendants count"=2
I0815 03:08:21.236973   10535 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-vg58l" "namespace"="default" "count"=1
I0815 03:08:21.237032   10535 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-vg58l" "namespace"="default" "descendants"="Control plane machines: test6-tv47p" "indirect descendants count"=0
I0815 03:08:21.243915   10535 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rd8q8-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0815 03:08:21.243956   10535 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-rd8q8-74d45c49c5" "namespace"="md-test" 
E0815 03:08:21.253735   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-62td4: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-62td4" "namespace"="default"
I0815 03:08:21.254159   10535 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rd8q8-74d45c49c5-7m949\"" "machineset"="md-rd8q8-74d45c49c5" "namespace"="md-test" 
E0815 03:08:21.452300   10535 machinedeployment_controller.go:149] controllers/MachineDeployment "msg"="Failed to reconcile MachineDeployment" "error"="MachineDeployment.cluster.x-k8s.io \"md-rd8q8\" not found" "machinedeployment"="md-rd8q8" "namespace"="md-test" 
E0815 03:08:21.452692   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="MachineDeployment.cluster.x-k8s.io \"md-rd8q8\" not found" "controller"="machinedeployment" "name"="md-rd8q8" "namespace"="md-test"
•I0815 03:08:21.456899   10535 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"
I0815 03:08:21.457801   10535 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0815 03:08:21.457869   10535 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"
I0815 03:08:21.458470   10535 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0815 03:08:21.458500   10535 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0815 03:08:21.460408   10535 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
... skipping 13 lines ...
I0815 03:08:21.473854   10535 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"
•I0815 03:08:21.475301   10535 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"
I0815 03:08:21.476001   10535 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"
I0815 03:08:21.476633   10535 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0815 03:08:21.476661   10535 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0815 03:08:21.477542   10535 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0815 03:08:21.479382   10535 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" 
•

Ran 16 of 16 Specs in 14.590 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (14.59s)
PASS
Tearing down test suite
I0815 03:08:21.481867   10535 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0815 03:08:21.481891   10535 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0815 03:08:21.481920   10535 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0815 03:08:21.482019   10535 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0815 03:08:21.482050   10535 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0815 03:08:21.482101   10535 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-600247161/tls.crt: no such file or directory"  
I0815 03:08:21.481867   10535 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0815 03:08:21.482147   10535 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0815 03:08:21.482224   10535 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0815 03:08:21.483980   10535 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="md-rd8q8-6657c7fddb-s8vhm" "namespace"="md-test" "err"="Get http://127.0.0.1:34781/apis/apiextensions.k8s.io/v1/customresourcedefinitions/infrastructuremachines.infrastructure.cluster.x-k8s.io: dial tcp 127.0.0.1:34781: connect: connection refused"
I0815 03:08:21.484814   10535 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-rd8q8-6657c7fddb-s8vhm" "namespace"="md-test" 
E0815 03:08:21.485971   10535 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[failed to retrieve InfrastructureMachine external object \"md-test\"/\"md-template-dhclk\": Get http://127.0.0.1:34781/apis/infrastructure.cluster.x-k8s.io/v1alpha3/namespaces/md-test/infrastructuremachines/md-template-dhclk: dial tcp 127.0.0.1:34781: connect: connection refused, Patch http://127.0.0.1:34781/apis/cluster.x-k8s.io/v1alpha3/namespaces/md-test/machines/md-rd8q8-6657c7fddb-s8vhm/status: dial tcp 127.0.0.1:34781: connect: connection refused]" "controller"="machine" "name"="md-rd8q8-6657c7fddb-s8vhm" "namespace"="md-test"
E0815 03:08:21.522205   10535 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:34781/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1256&timeout=10s&timeoutSeconds=504&watch=true: dial tcp 127.0.0.1:34781: connect: connection refused
E0815 03:08:21.522222   10535 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:34781/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1256&timeout=10s&timeoutSeconds=569&watch=true: dial tcp 127.0.0.1:34781: connect: connection refused
E0815 03:08:21.522290   10535 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:34781/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1256&timeout=10s&timeoutSeconds=593&watch=true: dial tcp 127.0.0.1:34781: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	56.294s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 256 lines ...
I0815 03:07:38.897353   10947 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"
I0815 03:07:38.897371   10947 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0815 03:07:38.897743   10947 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0815 03:07:38.907595   10947 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0815 03:07:38.907845   10947 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0815 03:07:38.908089   10947 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=34051
E0815 03:07:41.045279   10947 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-b6fdx/test-cluster"
•E0815 03:07:41.502808   10947 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-wzq5t/test-cluster"
•E0815 03:07:42.072446   10947 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:35359/?timeout=50ms: dial tcp 127.0.0.1:35359: connect: connection refused"  "cluster"="cluster-cache-test-qh8sq/test-cluster"
•I0815 03:07:42.299184   10947 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}}}
I0815 03:07:42.399565   10947 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0815 03:07:42.399627   10947 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0815 03:07:42.559733   10947 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0815 03:07:42.581715   10947 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":{}}}
I0815 03:07:42.782211   10947 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0815 03:07:42.782286   10947 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0815 03:07:42.782376   10947 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0815 03:07:43.318033   10947 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0815 03:07:43.318097   10947 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
I0815 03:07:43.318156   10947 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0815 03:07:43.318171   10947 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-673249945/tls.crt: no such file or directory"  
E0815 03:07:43.318192   10947 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 03:07:43.318212   10947 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-673249945/tls.crt: no such file or directory"  
E0815 03:07:43.402593   10947 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:33733/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:33733: connect: connection refused


Ran 5 of 5 Specs in 16.376 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.38s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	16.538s
?   	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
I0815 03:07:50.636782   11640 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
E0815 03:07:50.638077   11640 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
I0815 03:07:50.638693   11640 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0815 03:07:50.638894   11640 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
I0815 03:08:05.441271   11640 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
I0815 03:08:05.441381   11640 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: 1660532857
Will run 1 of 1 specs

E0815 03:08:05.475584   11640 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-pj5xxl\" not found" "kubeadmControlPlane"="kcp-foo-pj5xxl" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.031 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0815 03:08:05.477127   11640 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-jykkak" "kubeadmControlPlane"="kcp-foo-jykkak" "namespace"="test" 
I0815 03:08:07.881145   11640 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-jykkak" "kubeadmControlPlane"="kcp-foo-jykkak" "namespace"="test" "needRollout"=["kcp-foo-jykkak-xpgqc"]
I0815 03:08:07.881404   11640 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-jykkak" "kubeadmControlPlane"="kcp-foo-jykkak" "namespace"="test" "failures"="[machine kcp-foo-jykkak-8xv9n does not have APIServerPodHealthy condition, machine kcp-foo-jykkak-8xv9n does not have ControllerManagerPodHealthy condition, machine kcp-foo-jykkak-8xv9n does not have SchedulerPodHealthy condition, machine kcp-foo-jykkak-8xv9n does not have EtcdPodHealthy condition, machine kcp-foo-jykkak-8xv9n does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.41s)
... skipping 60 lines ...
==================================
Random Seed: 1660532856
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestControlPlane (0.00s)
=== RUN   TestHasUnhealthyMachine
--- PASS: TestHasUnhealthyMachine (0.00s)
=== RUN   TestNewFailureDomainPicker
=== RUN   TestNewFailureDomainPicker/simple
=== RUN   TestNewFailureDomainPicker/no_machines
... skipping 111 lines ...
=======================================
Random Seed: 1660532856
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 297 lines ...
    --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s)
    --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s)
=== RUN   TestRemoveMachineFromKubeadmConfigMap
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0
E0815 03:07:49.137804   11575 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"  
E0815 03:07:57.460925   11575 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"  
E0815 03:08:06.446860   11575 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"  
E0815 03:08:17.577151   11575 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"  
E0815 03:08:34.050343   11575 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"  
E0815 03:08:47.058969   11575 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"  
E0815 03:09:04.706516   11575 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"  
E0815 03:09:25.629938   11575 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"  
E0815 03:09:56.646479   11575 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"  
E0815 03:10:41.803689   11575 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 84 lines ...
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s)
PASS
I0815 03:10:41.814143   11575 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0815 03:10:41.814270   11575 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0815 03:10:41.814324   11575 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-264368330/tls.crt: no such file or directory"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	185.799s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
... skipping 287 lines ...
I0815 03:07:59.732804   11922 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" 
I0815 03:07:59.835125   11922 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0815 03:07:59.935529   11922 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0815 03:07:59.935758   11922 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0815 03:07:59.935798   11922 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0815 03:08:00.005976   11922 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-l0h0jz"} 
E0815 03:08:00.202875   11922 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"
•I0815 03:08:01.251710   11922 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-mphz9i"} 
E0815 03:08:01.290417   11922 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"
•E0815 03:08:12.379176   11922 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"

------------------------------
• Failure [11.090 seconds]
ClusterResourceSet Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:40
  Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources [It]
... skipping 8 lines ...
------------------------------
STEP: Creating the Cluster
STEP: Creating the remote Cluster kubeconfig
STEP: Creating a Secret and a ConfigMap with ConfigMap in their data field
STEP: Verifying ClusterResourceSetBinding is created with cluster owner reference
STEP: Deleting the Kubeconfigsecret
E0815 03:08:13.515347   11922 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"
E0815 03:08:14.540610   11922 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"
•E0815 03:08:15.562491   11922 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"
•I0815 03:08:15.563255   11922 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0815 03:08:15.563297   11922 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0815 03:08:15.563379   11922 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  



Summarizing 1 Failure:

[Fail] ClusterResourceSet Reconciler [It] Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources 
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:307

Ran 5 of 5 Specs in 29.848 seconds
FAIL! -- 4 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestAPIs (29.85s)
FAIL
FAIL	sigs.k8s.io/cluster-api/exp/addons/controllers	29.956s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-create
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-update
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-delete
... skipping 58 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0815 03:07:50.950002   12133 machinepool_controller_phases.go:237]  "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
=== RUN   TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused
--- PASS: TestReconcileMachinePoolInfrastructure (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestMachinePoolFinalizer
... skipping 92 lines ...
•I0815 03:08:03.543116   12133 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0815 03:08:03.565682   12133 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0815 03:08:03.567840   12133 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0815 03:08:03.593302   12133 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0815 03:08:03.629005   12133 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••I0815 03:08:03.631572   12133 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0815 03:08:03.631677   12133 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0815 03:08:03.631724   12133 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-814128396/tls.crt: no such file or directory"  
I0815 03:08:03.667447   12133 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinepool" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}


Ran 9 of 9 Specs in 12.698 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (12.70s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	12.871s
?   	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 ...
I0815 03:08:26.439827   15089 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=46277
I0815 03:08:26.440659   15089 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••I0815 03:08:27.275352   15089 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 14 of 14 Specs in 7.163 seconds
SUCCESS! -- 14 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestPatch (7.16s)
=== 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.048s
FAIL
make: *** [Makefile:116: test] Error 1