This job view page is being replaced by Spyglass soon. Check out the new job view.
PRsbueringer: ✨ v0.3.x: KCP: block mgmt cluster updates to v1.22.0
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-28 18:11
Elapsed4m32s
Revision9663f2775ef2002737b1d52e369f2d2914e31abe
Refs 5013

No Test Failures!


Error lines from build-log.txt

... skipping 781 lines ...
I0728 18:12:59.640382    8505 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0728 18:13:00.237436    8505 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" 
•I0728 18:13:00.250479    8505 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 13.130 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.13s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	64.329s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 310 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 1403 lines ...
I0728 18:12:32.411766   10588 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0728 18:12:32.693365   10588 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"
2021/07/28 18:12:32 http: TLS handshake error from 127.0.0.1:33656: EOF
I0728 18:12:32.696611   10588 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
I0728 18:12:32.697226   10588 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test-cluster" "namespace"="test-namespace" "err"="cannot create a metadata client without a rest config"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_is_marked_ready_on_cluster
I0728 18:12:32.698954   10588 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test-cluster" "namespace"="test-namespace" "err"="cannot create a metadata client without a rest config"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_infrastructure_has_the_paused_annotation
... skipping 100 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0728 18:12:32.722678   10588 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
I0728 18:12:32.734542   10588 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"
E0728 18:12:32.735041   10588 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
I0728 18:12:32.735558   10588 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.00s)
=== RUN   TestWatches
I0728 18:12:33.086397   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0728 18:12:33.187199   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0728 18:12:33.198861   10588 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0728 18:12:33.198972   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0728 18:12:33.309188   10588 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0728 18:12:33.309286   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0728 18:12:33.409841   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99" "noderef"="node-1"
E0728 18:12:33.421430   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0728 18:12:33.421492   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0728 18:12:33.443426   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99" "noderef"="node-1"
E0728 18:12:33.479423   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-9sc5h\" in namespace \"test-machine-watches-nxs99\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99"
E0728 18:12:34.483697   10588 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-9sc5h\" in namespace \"test-machine-watches-nxs99\", requeuing: requeue in 1s"  
E0728 18:12:34.489440   10588 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-9sc5h\" in namespace \"test-machine-watches-nxs99\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-9sc5h\" in namespace \"test-machine-watches-nxs99\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99"
--- PASS: TestWatches (1.78s)
=== 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
I0728 18:12:34.613603   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-nbfrw" "namespace"="test-machine-watches-nxs99" "count"=1
I0728 18:12:34.613665   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-nbfrw" "namespace"="test-machine-watches-nxs99" "descendants"="Worker machines: machine-created-9sc5h" "indirect descendants count"=0
I0728 18:12:34.629251   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-nbfrw" "namespace"="test-machine-watches-nxs99" "count"=1
I0728 18:12:34.629316   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-nbfrw" "namespace"="test-machine-watches-nxs99" "descendants"="Worker machines: machine-created-9sc5h" "indirect descendants count"=0
I0728 18:12:35.495369   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-nbfrw" "machine"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"48866c26-6cd7-473d-b463-0a99f0cac932","apiVersion":"v1"}
E0728 18:12:35.549631   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-9sc5h\" not found" "controller"="machine" "name"="machine-created-9sc5h" "namespace"="test-machine-watches-nxs99"
E0728 18:12:36.604843   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-rvtrp\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-np8pw\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-np8pw: secrets \"machine-reconcile-np8pw-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-rvtrp" "namespace"="default"
I0728 18:12:37.605515   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-np8pw" "machine"="machine-created-rvtrp" "namespace"="default" "cause"="noderef is nil" "node"=null
I0728 18:12:37.637400   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-np8pw" "machine"="machine-created-rvtrp" "namespace"="default" "cause"="noderef is nil" "node"=null
I0728 18:12:37.691719   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-np8pw" "machine"="machine-created-rvtrp" "namespace"="default" "cause"="noderef is nil" "node"=null
E0728 18:12:37.744024   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-rvtrp\" not found" "controller"="machine" "name"="machine-created-rvtrp" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.27s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.27s)
=== 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 4 lines ...
I0728 18:12:37.789971   10588 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine2" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0728 18:12:37.790234   10588 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine2" "namespace"="default" 
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set
I0728 18:12:37.796107   10588 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"
I0728 18:12:37.796234   10588 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
E0728 18:12:37.800980   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-np8pw\" not found" "controller"="cluster" "name"="machine-reconcile-np8pw" "namespace"="default"
I0728 18:12:37.808293   10588 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"
I0728 18:12:37.808416   10588 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
--- PASS: TestMachineOwnerReference (0.03s)
    --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.01s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.01s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s)
... skipping 122 lines ...
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0728 18:12:38.073112   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qm65q" "namespace"="test-mhc-5n67x" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I0728 18:12:38.136273   10588 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
E0728 18:12:38.137047   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-bgtht\" not found"  "cluster"="test-mhc-5n67x/test-cluster-bgtht"
E0728 18:12:38.141870   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-qm65q\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-qm65q\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-qm65q" "namespace"="test-mhc-5n67x"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist
I0728 18:12:39.142166   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vtdnh" "namespace"="test-mhc-fs4nm" 
I0728 18:12:39.142289   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qm65q" "namespace"="test-mhc-5n67x" 
I0728 18:12:39.142325   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jtlmq" "namespace"="test-mhc-lr8gk" 
I0728 18:12:39.142361   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cczxn" "namespace"="test-mhc-87j58" 
I0728 18:12:39.172274   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:12:39.192728   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cczxn" "namespace"="test-mhc-87j58" 
I0728 18:12:39.219976   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cczxn" "namespace"="test-mhc-87j58" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
E0728 18:12:39.228880   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-87j58/test-cluster-bmsb4"
E0728 18:12:39.230919   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-bmsb4\" not found" "controller"="cluster" "name"="test-cluster-bmsb4" "namespace"="test-mhc-87j58"
I0728 18:12:39.338701   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2rsm" "namespace"="test-mhc-d5gl4" 
I0728 18:12:39.351530   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:12:39.469972   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2rsm" "namespace"="test-mhc-d5gl4" 
E0728 18:12:39.546058   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-d5gl4/test-cluster-98459"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0728 18:12:39.552877   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2rsm" "namespace"="test-mhc-d5gl4" 
I0728 18:12:39.574637   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
inframachine created: test-mhc-machine-infra-7q9gr
I0728 18:12:39.625287   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-pdvbp
I0728 18:12:39.659726   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.665490   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.665934   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:39.679008   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.679360   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:39.688626   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.689209   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:39.708136   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.708723   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:39.712756   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.713304   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:39.725629   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.726015   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
E0728 18:12:39.737069   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-vd27w, got []"  "node"="test-mhc-node-vd27w"
E0728 18:12:39.737325   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-vd27w"
node created: test-mhc-node-vd27w
I0728 18:12:39.739758   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.740135   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:39.750105   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.751692   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d" "noderef"="test-mhc-node-vd27w"
inframachine created: test-mhc-machine-infra-mn8zx
I0728 18:12:39.773025   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.775749   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.784998   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
... skipping 14 lines ...
I0728 18:12:39.859239   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.860580   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.861694   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.862769   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.865089   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.868156   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.868643   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-n5xv6/"
I0728 18:12:39.889696   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.890128   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-n5xv6/"
node created: test-mhc-node-dvjrq
E0728 18:12:39.891444   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-dvjrq"
E0728 18:12:39.891510   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dvjrq, got []"  "node"="test-mhc-node-dvjrq"
I0728 18:12:39.897843   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.898349   10588 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-4mv9d/test-mhc-s9m6w/test-mhc-machine-n5xv6/"
I0728 18:12:39.903949   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.946430   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
Cleaning up nodes, machines and infra machines.
I0728 18:12:39.952726   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:39.954356   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:40.003466   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:40.004232   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-4mv9d/test-mhc-s9m6w/test-mhc-machine-pdvbp/"
I0728 18:12:40.005049   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-4mv9d/test-mhc-s9m6w/test-mhc-machine-n5xv6/"
E0728 18:12:40.007579   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-4mv9d/test-cluster-tktqs"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0728 18:12:40.024479   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
E0728 18:12:40.025063   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-s9m6w\" not found" "controller"="machinehealthcheck" "name"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d"
inframachine created: test-mhc-machine-infra-sggd9
machine created: test-mhc-machine-ssr2j
E0728 18:12:40.245461   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-nxs99/machine-reconcile-nbfrw"
E0728 18:12:41.024919   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:41.025258   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s9m6w" "namespace"="test-mhc-4mv9d" 
I0728 18:12:41.025332   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:41.043509   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:12:41.168124   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:41.174748   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:41.176420   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 427 lines ...
I0728 18:12:42.013362   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.015421   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.017398   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.019338   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.021687   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.023608   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:42.025333   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:42.025369   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.027117   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.028709   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.030402   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.032026   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:42.033730   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 483 lines ...
I0728 18:12:43.033726   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.034405   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.035484   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.037192   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.038983   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.041062   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:43.041578   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:43.041583   10588 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-p4rn7/test-mhc-fb6b6/test-mhc-machine-ssr2j/"
I0728 18:12:43.056094   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.056454   10588 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-p4rn7/test-mhc-fb6b6/test-mhc-machine-ssr2j/"
E0728 18:12:43.068059   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d7x8k, got []"  "node"="test-mhc-node-d7x8k"
node created: test-mhc-node-d7x8k
I0728 18:12:43.076286   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
inframachine created: test-mhc-machine-infra-smrqc
machine created: test-mhc-machine-9xz24
I0728 18:12:43.106852   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:43.116853   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 311 lines ...
I0728 18:12:44.030192   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.032249   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.034361   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.036438   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.038570   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.040993   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:44.042179   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:44.049417   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.051593   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.053602   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.055615   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.057607   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:44.059652   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 365 lines ...
I0728 18:12:45.080157   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.082441   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.084558   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.090658   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.093836   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.097047   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:45.098388   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:45.099583   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.100866   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.101901   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.104016   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.106379   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:45.108615   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 325 lines ...
I0728 18:12:46.101340   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.103756   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.106394   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.108507   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.109621   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.111804   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:46.113628   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:46.114558   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.115158   10588 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-p4rn7/test-mhc-fb6b6/test-mhc-machine-9xz24/"
I0728 18:12:46.126735   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.127241   10588 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-p4rn7/test-mhc-fb6b6/test-mhc-machine-9xz24/"
node created: test-mhc-node-fgqw4
E0728 18:12:46.149547   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fgqw4, got []"  "node"="test-mhc-node-fgqw4"
I0728 18:12:46.157678   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
inframachine created: test-mhc-machine-infra-fpbgq
machine created: test-mhc-machine-6phxr
I0728 18:12:46.198955   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.208126   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:46.209766   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 263 lines ...
I0728 18:12:47.114885   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.117070   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.130786   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.134203   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.137375   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.139702   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:47.139739   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:47.142076   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.143621   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.145347   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.146879   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.148206   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:47.149314   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 265 lines ...
I0728 18:12:48.154699   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.157599   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.159738   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.161607   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.164129   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.180741   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
E0728 18:12:48.185976   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:48.187402   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.189255   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.191795   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.193830   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.195354   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:48.196976   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
... skipping 269 lines ...
I0728 18:12:49.191922   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.196223   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.201035   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.203281   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.207414   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.210761   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.211561   10588 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-p4rn7/test-mhc-fb6b6/test-mhc-machine-6phxr/"
node created: test-mhc-node-d26k6
E0728 18:12:49.221433   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d26k6, got []"  "node"="test-mhc-node-d26k6"
E0728 18:12:49.221835   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
Cleaning up nodes, machines and infra machines.
I0728 18:12:49.229606   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.230598   10588 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-p4rn7/test-mhc-fb6b6/test-mhc-machine-6phxr/test-mhc-node-d26k6"
Cleaning up nodes, machines and infra machines.
I0728 18:12:49.250873   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.251470   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-p4rn7/test-mhc-fb6b6/test-mhc-machine-6phxr/"
I0728 18:12:49.277083   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:49.277646   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-p4rn7/test-mhc-fb6b6/test-mhc-machine-ssr2j/"
I0728 18:12:49.298584   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nf866" "namespace"="test-mhc-p4rn7" "count"=2
I0728 18:12:49.298665   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nf866" "namespace"="test-mhc-p4rn7" "descendants"="Worker machines: test-mhc-machine-6phxr,test-mhc-machine-ssr2j,test-mhc-machine-9xz24" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
I0728 18:12:49.308679   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nf866" "namespace"="test-mhc-p4rn7" "count"=2
I0728 18:12:49.308741   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nf866" "namespace"="test-mhc-p4rn7" "descendants"="Worker machines: test-mhc-machine-ssr2j,test-mhc-machine-9xz24,test-mhc-machine-6phxr" "indirect descendants count"=1
I0728 18:12:49.417688   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-p4rn7/test-mhc-fb6b6/test-mhc-machine-9xz24/"
I0728 18:12:49.430586   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-p4rn7/test-mhc-fb6b6/test-mhc-machine-6phxr/"
E0728 18:12:49.433937   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-fb6b6\" not found" "controller"="machinehealthcheck" "name"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7"
inframachine created: test-mhc-machine-infra-tfmx9
machine created: test-mhc-machine-lzjl2
I0728 18:12:50.222383   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nf866" "machine"="test-mhc-machine-9xz24" "namespace"="test-mhc-p4rn7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-fgqw4"}
E0728 18:12:50.270724   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9xz24\" not found" "controller"="machine" "name"="test-mhc-machine-9xz24" "namespace"="test-mhc-p4rn7"
I0728 18:12:50.434254   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fb6b6" "namespace"="test-mhc-p4rn7" 
I0728 18:12:50.434367   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:50.456948   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:12:50.500455   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:50.505655   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:50.527431   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:50.571551   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:50.652593   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:50.813637   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:51.134669   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:51.271147   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:51.776023   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:52.271707   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nf866" "machine"="test-mhc-machine-6phxr" "namespace"="test-mhc-p4rn7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-d26k6"}
E0728 18:12:52.321209   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-6phxr\" not found" "controller"="machine" "name"="test-mhc-machine-6phxr" "namespace"="test-mhc-p4rn7"
I0728 18:12:53.057069   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:53.321728   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nf866" "machine"="test-mhc-machine-ssr2j" "namespace"="test-mhc-p4rn7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-d7x8k"}
E0728 18:12:53.368979   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-ssr2j\" not found" "controller"="machine" "name"="test-mhc-machine-ssr2j" "namespace"="test-mhc-p4rn7"
E0728 18:12:54.323861   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-p4rn7/test-cluster-nf866"
E0728 18:12:54.369375   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:55.383804   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.397731   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:55.399403   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:55.434789   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:55.492172   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-nf644, got []"  "node"="test-mhc-node-nf644"
node created: test-mhc-node-nf644
I0728 18:12:55.500631   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
inframachine created: test-mhc-machine-infra-q2c7n
machine created: test-mhc-machine-cjw47
I0728 18:12:55.520334   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.533770   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.539166   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.560454   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.602642   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.684148   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:55.845515   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:56.173733   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:56.399810   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:56.824547   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.416604   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.429921   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.438777   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.453613   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.465676   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:57.473157   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:57.473481   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.506058   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:57.546619   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-nvpz6, got []"  "node"="test-mhc-node-nvpz6"
node created: test-mhc-node-nvpz6
I0728 18:12:57.554347   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
inframachine created: test-mhc-machine-infra-fhhx5
I0728 18:12:57.572011   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
machine created: test-mhc-machine-rswvx
I0728 18:12:57.573960   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:57.587904   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:58.105871   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:58.473556   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:12:59.494103   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.528559   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.535437   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.571534   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.583407   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.595445   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.600545   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:59.600554   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:12:59.629938   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
E0728 18:12:59.691575   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hwzgf, got []"  "node"="test-mhc-node-hwzgf"
node created: test-mhc-node-hwzgf
I0728 18:12:59.701447   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
Cleaning up nodes, machines and infra machines.
I0728 18:12:59.718064   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.733334   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.749118   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
Cleaning up nodes, machines and infra machines.
I0728 18:12:59.772208   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:12:59.811644   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-hj246" "namespace"="test-mhc-4fzmj" "count"=2
I0728 18:12:59.811731   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hj246" "namespace"="test-mhc-4fzmj" "descendants"="Worker machines: test-mhc-machine-lzjl2,test-mhc-machine-cjw47,test-mhc-machine-rswvx" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
I0728 18:12:59.859904   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-hj246" "namespace"="test-mhc-4fzmj" "count"=2
I0728 18:12:59.859979   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hj246" "namespace"="test-mhc-4fzmj" "descendants"="Worker machines: test-mhc-machine-lzjl2,test-mhc-machine-cjw47,test-mhc-machine-rswvx" "indirect descendants count"=1
E0728 18:12:59.921056   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-qn7b6\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-qn7b6\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj"
inframachine created: test-mhc-machine-infra-6lgz7
machine created: test-mhc-machine-5b4xk
I0728 18:13:00.602132   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hj246" "machine"="test-mhc-machine-lzjl2" "namespace"="test-mhc-4fzmj" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-nf644"}
E0728 18:13:00.655459   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-lzjl2\" not found" "controller"="machine" "name"="test-mhc-machine-lzjl2" "namespace"="test-mhc-4fzmj"
I0728 18:13:00.921487   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qn7b6" "namespace"="test-mhc-4fzmj" 
I0728 18:13:00.921649   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:00.947153   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:13:00.966779   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:00.974345   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:01.656070   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hj246" "machine"="test-mhc-machine-cjw47" "namespace"="test-mhc-4fzmj" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-nvpz6"}
E0728 18:13:01.711946   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-cjw47\" not found" "controller"="machine" "name"="test-mhc-machine-cjw47" "namespace"="test-mhc-4fzmj"
I0728 18:13:02.712530   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hj246" "machine"="test-mhc-machine-rswvx" "namespace"="test-mhc-4fzmj" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hwzgf"}
E0728 18:13:02.765633   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-rswvx\" not found" "controller"="machine" "name"="test-mhc-machine-rswvx" "namespace"="test-mhc-4fzmj"
E0728 18:13:03.766129   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:13:04.775123   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:04.785782   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
E0728 18:13:04.786009   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
node created: test-mhc-node-rhw2d
E0728 18:13:04.796739   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-rhw2d, got []"  "node"="test-mhc-node-rhw2d"
E0728 18:13:04.797089   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-rhw2d, got []"  "node"="test-mhc-node-rhw2d"
I0728 18:13:04.809914   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
inframachine created: test-mhc-machine-infra-qsn48
machine created: test-mhc-machine-lxckk
E0728 18:13:04.871432   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-4fzmj/test-cluster-hj246"
I0728 18:13:04.874706   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:04.883283   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.817551   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.832534   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.845279   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.869126   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.883010   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.892976   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.920982   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.935045   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:05.941155   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
E0728 18:13:05.959036   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-nllln, got []"  "node"="test-mhc-node-nllln"
node created: test-mhc-node-nllln
I0728 18:13:05.963961   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-lxckk" "namespace"="test-mhc-7bd7q" "noderef"="test-mhc-node-nllln"
E0728 18:13:05.969364   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-nllln, got []"  "node"="test-mhc-node-nllln"
E0728 18:13:05.969414   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-nllln, got []"  "node"="test-mhc-node-nllln"
I0728 18:13:05.973767   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
inframachine created: test-mhc-machine-infra-kxnlp
I0728 18:13:05.995063   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
machine created: test-mhc-machine-8kt8f
I0728 18:13:06.003871   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:06.013313   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
... skipping 9 lines ...
I0728 18:13:06.225011   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:06.225855   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-gkdsn" "machine"="test-mhc-machine-8kt8f" "namespace"="test-mhc-7bd7q" "cause"="noderef is nil" "node"=null
I0728 18:13:06.237352   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
Cleaning up nodes, machines and infra machines.
I0728 18:13:06.239742   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:06.244391   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:06.245008   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7bd7q/test-mhc-qhqzf/test-mhc-machine-5b4xk/"
I0728 18:13:06.281073   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:06.282170   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7bd7q/test-mhc-qhqzf/test-mhc-machine-lxckk/"
E0728 18:13:06.306087   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-8kt8f\" not found" "controller"="machine" "name"="test-mhc-machine-8kt8f" "namespace"="test-mhc-7bd7q"
I0728 18:13:06.318742   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-gkdsn" "namespace"="test-mhc-7bd7q" "count"=2
I0728 18:13:06.318854   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-gkdsn" "namespace"="test-mhc-7bd7q" "descendants"="Worker machines: test-mhc-machine-5b4xk,test-mhc-machine-lxckk" "indirect descendants count"=0
I0728 18:13:06.325614   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-gkdsn" "namespace"="test-mhc-7bd7q" "count"=2
I0728 18:13:06.325693   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-gkdsn" "namespace"="test-mhc-7bd7q" "descendants"="Worker machines: test-mhc-machine-5b4xk,test-mhc-machine-lxckk" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_longer_than_the_NodeStartupTimeout
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine's_Node_has_gone_away
=== RUN   TestMachineHealthCheck_Reconcile/should_react_when_a_Node_transitions_to_unhealthy
inframachine created: test-mhc-machine-infra-hch9m
machine created: test-mhc-machine-frcnh
I0728 18:13:06.473888   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7bd7q/test-mhc-qhqzf/test-mhc-machine-5b4xk/"
E0728 18:13:06.477242   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-qhqzf\" not found" "controller"="machinehealthcheck" "name"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q"
I0728 18:13:07.306642   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-gkdsn" "machine"="test-mhc-machine-5b4xk" "namespace"="test-mhc-7bd7q" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-rhw2d"}
E0728 18:13:07.365919   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5b4xk\" not found" "controller"="machine" "name"="test-mhc-machine-5b4xk" "namespace"="test-mhc-7bd7q"
I0728 18:13:07.477574   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:07.491434   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:13:07.621243   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qhqzf" "namespace"="test-mhc-7bd7q" 
I0728 18:13:07.621296   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:07.622741   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:07.624578   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
... skipping 317 lines ...
I0728 18:13:08.411682   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.415242   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.418999   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.422656   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.426369   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.428822   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
E0728 18:13:08.429372   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-lxckk\" not found" "controller"="machine" "name"="test-mhc-machine-lxckk" "namespace"="test-mhc-7bd7q"
I0728 18:13:08.430697   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.432751   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.434504   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.436187   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.437841   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:08.439566   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
... skipping 437 lines ...
I0728 18:13:09.419402   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.421091   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.423184   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.424907   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.426693   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.428471   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
E0728 18:13:09.429706   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:13:09.430187   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.431891   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.433611   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.435386   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.444977   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:09.446968   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
... skipping 435 lines ...
I0728 18:13:10.432375   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.437643   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.439417   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.442088   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.443004   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.443785   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
E0728 18:13:10.445490   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:13:10.445771   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.445993   10588 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-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/"
I0728 18:13:10.456720   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.457064   10588 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-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/"
E0728 18:13:10.529924   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-n4mh7, got []"  "node"="test-mhc-node-n4mh7"
node created: test-mhc-node-n4mh7
E0728 18:13:10.530773   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-n4mh7, got []"  "node"="test-mhc-node-n4mh7"
I0728 18:13:10.538026   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.554452   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.562294   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.562819   10588 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-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/test-mhc-node-n4mh7"
I0728 18:13:10.585802   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.586186   10588 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-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/test-mhc-node-n4mh7"
I0728 18:13:10.592214   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.592619   10588 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-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/test-mhc-node-n4mh7"
Cleaning up nodes, machines and infra machines.
I0728 18:13:10.602815   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.603185   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/"
I0728 18:13:10.615549   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.615908   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tkpsk/test-mhc-h4mbr/test-mhc-machine-frcnh/"
I0728 18:13:10.624284   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-frj4d" "namespace"="test-mhc-tkpsk" "descendants"="Worker machines: test-mhc-machine-frcnh" "indirect descendants count"=1
I0728 18:13:10.628694   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-frj4d" "namespace"="test-mhc-tkpsk" "descendants"="Worker machines: test-mhc-machine-frcnh" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0728 18:13:10.636565   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-h4mbr" "namespace"="test-mhc-tkpsk" 
I0728 18:13:10.868426   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" "creating"=1 "need"=1
I0728 18:13:10.868501   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:10.880647   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-4qg9j-fqtd6\"" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:10.948817   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:10.969428   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 18:13:10.987156   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:11.103651   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:11.117495   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
E0728 18:13:11.339950   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-7bd7q/test-cluster-gkdsn"
I0728 18:13:11.446240   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-frj4d" "machine"="test-mhc-machine-frcnh" "namespace"="test-mhc-tkpsk" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-n4mh7"}
E0728 18:13:11.489479   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-frcnh\" not found" "controller"="machine" "name"="test-mhc-machine-frcnh" "namespace"="test-mhc-tkpsk"
I0728 18:13:12.103878   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.505238   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.506222   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.522783   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.523569   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.541682   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
... skipping 2 lines ...
I0728 18:13:12.549911   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.561533   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.562446   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.568941   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
I0728 18:13:12.568984   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.105327   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.105833   10588 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-2j7rg/test-mhc-wbhq2/mhc-ms-4qg9j-fqtd6/"
I0728 18:13:13.114422   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.120546   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.120611   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.122306   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.122664   10588 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-2j7rg/test-mhc-wbhq2/mhc-ms-4qg9j-fqtd6/"
I0728 18:13:13.133727   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.134091   10588 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-2j7rg/test-mhc-wbhq2/mhc-ms-4qg9j-fqtd6/"
I0728 18:13:13.135015   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.148808   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.148952   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.204871   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-tsz65" "namespace"="test-mhc-2j7rg" "count"=1
I0728 18:13:13.208461   10588 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" "machine"="mhc-ms-4qg9j-fqtd6"
I0728 18:13:13.212546   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wbhq2" "namespace"="test-mhc-2j7rg" 
I0728 18:13:13.213008   10588 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-tsz65" "namespace"="test-mhc-2j7rg" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-4qg9j"
I0728 18:13:13.224787   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-tsz65" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" "cause"="cluster is being deleted" "node"=null
I0728 18:13:13.228500   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-tsz65" "namespace"="test-mhc-2j7rg" "descendants"="Machine sets: mhc-ms-4qg9j;Worker machines: mhc-ms-4qg9j-fqtd6" "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
E0728 18:13:13.235041   10588 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-4qg9j\" not found" "machineset"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg" 
E0728 18:13:13.235126   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-4qg9j\" not found" "controller"="machineset" "name"="mhc-ms-4qg9j" "namespace"="test-mhc-2j7rg"
I0728 18:13:13.239101   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-tsz65" "namespace"="test-mhc-2j7rg" "descendants"="Worker machines: mhc-ms-4qg9j-fqtd6" "indirect descendants count"=1
I0728 18:13:13.349386   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
inframachine created: test-mhc-machine-infra-swhmv
I0728 18:13:13.380031   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-nb2v7
I0728 18:13:13.433079   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
... skipping 15 lines ...
I0728 18:13:13.472253   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.473030   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.474134   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.475911   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.477738   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-tsz65" "machine"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg" "cause"="cluster is being deleted" "node"=null
I0728 18:13:13.477768   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
E0728 18:13:13.534307   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-4qg9j-fqtd6\" not found" "controller"="machine" "name"="mhc-ms-4qg9j-fqtd6" "namespace"="test-mhc-2j7rg"
node created: test-mhc-node-c8bmn
E0728 18:13:13.539194   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c8bmn, got []"  "node"="test-mhc-node-c8bmn"
E0728 18:13:13.539512   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c8bmn, got []"  "node"="test-mhc-node-c8bmn"
E0728 18:13:13.539838   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c8bmn, got []"  "node"="test-mhc-node-c8bmn"
I0728 18:13:13.567079   10588 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-nb2v7" "target"="test-mhc-kjkk8/test-mhc-bgcz9/test-mhc-machine-nb2v7/"
I0728 18:13:13.584474   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.619256   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.627465   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.636478   10588 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-nb2v7" "target"="test-mhc-kjkk8/test-mhc-bgcz9/test-mhc-machine-nb2v7/test-mhc-node-c8bmn"
I0728 18:13:13.660607   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
Cleaning up nodes, machines and infra machines.
I0728 18:13:13.677123   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.682330   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.686700   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bgcz9" "namespace"="test-mhc-kjkk8" 
I0728 18:13:13.696502   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-qkdf8" "namespace"="test-mhc-kjkk8" "descendants"="Worker machines: test-mhc-machine-nb2v7" "indirect descendants count"=1
... skipping 346 lines ...
I0728 18:13:14.580562   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.582827   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.586439   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.588453   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.590568   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.592673   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
E0728 18:13:14.593134   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-nb2v7\" not found" "controller"="machine" "name"="test-mhc-machine-nb2v7" "namespace"="test-mhc-kjkk8"
I0728 18:13:14.595029   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.596942   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.598942   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.601580   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.603983   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:14.607134   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
... skipping 398 lines ...
I0728 18:13:15.598084   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.600399   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.602541   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.603214   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.604623   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.607735   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
E0728 18:13:15.608182   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
I0728 18:13:15.608477   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.612477   10588 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-7nfhc" "target"="test-mhc-5rxwp/test-mhc-c8gbd/test-mhc-machine-7nfhc/"
E0728 18:13:15.632261   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6xsrk, got []"  "node"="test-mhc-node-6xsrk"
E0728 18:13:15.632375   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6xsrk, got []"  "node"="test-mhc-node-6xsrk"
E0728 18:13:15.632380   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6xsrk, got []"  "node"="test-mhc-node-6xsrk"
E0728 18:13:15.632514   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6xsrk, got []"  "node"="test-mhc-node-6xsrk"
node created: test-mhc-node-6xsrk
I0728 18:13:15.633465   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.647145   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
E0728 18:13:15.648207   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-tkpsk/test-cluster-frj4d"
I0728 18:13:15.674554   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.683950   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.689448   10588 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-7nfhc" "target"="test-mhc-5rxwp/test-mhc-c8gbd/test-mhc-machine-7nfhc/test-mhc-node-6xsrk"
I0728 18:13:15.711332   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.737099   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.788148   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.796130   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
Cleaning up nodes, machines and infra machines.
I0728 18:13:15.812460   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
I0728 18:13:15.818037   10588 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-7nfhc" "target"="test-mhc-5rxwp/test-mhc-c8gbd/test-mhc-machine-7nfhc/"
I0728 18:13:15.835727   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5ksgm" "namespace"="test-mhc-5rxwp" "descendants"="Worker machines: test-mhc-machine-7nfhc" "indirect descendants count"=1
I0728 18:13:15.841166   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5ksgm" "namespace"="test-mhc-5rxwp" "descendants"="Worker machines: test-mhc-machine-7nfhc" "indirect descendants count"=1
--- PASS: TestMachineHealthCheck_Reconcile (37.81s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.04s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.05s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.15s)
... skipping 12 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (0.48s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.14s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0728 18:13:15.850964   10588 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
E0728 18:13:15.852342   10588 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
E0728 18:13:15.853961   10588 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0728 18:13:15.854161   10588 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
E0728 18:13:15.854861   10588 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
I0728 18:13:15.858902   10588 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0728 18:13:15.859525   10588 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0728 18:13:15.861949   10588 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
E0728 18:13:15.873654   10588 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
E0728 18:13:15.875348   10588 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 57 lines ...
=== RUN   TestGinkgoSuite
Running Suite: Controllers Suite
================================
Random Seed: 1627495937
Will run 16 of 16 specs

E0728 18:13:15.982249   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-c8gbd\" not found" "controller"="machinehealthcheck" "name"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp"
•E0728 18:13:16.022254   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-rlcrp\" not found" "controller"="cluster" "name"="test1-rlcrp" "namespace"="default"
E0728 18:13:16.608808   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
I0728 18:13:16.982528   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c8gbd" "namespace"="test-mhc-5rxwp" 
•I0728 18:13:17.144200   10588 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-78b5j" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0728 18:13:17.262443   10588 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-78b5j" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0728 18:13:17.268295   10588 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-78b5j" "namespace"="default"
I0728 18:13:17.609362   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5ksgm" "machine"="test-mhc-machine-7nfhc" "namespace"="test-mhc-5rxwp" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6xsrk"}
E0728 18:13:17.657879   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-7nfhc\" not found" "controller"="machine" "name"="test-mhc-machine-7nfhc" "namespace"="test-mhc-5rxwp"
E0728 18:13:18.283973   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
•E0728 18:13:19.301536   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-2j7rg/test-cluster-tsz65"
E0728 18:13:19.317654   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-8vblz\" not found" "controller"="cluster" "name"="test3-8vblz" "namespace"="default"
E0728 18:13:20.318705   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
E0728 18:13:21.354180   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-kjkk8/test-cluster-qkdf8"
E0728 18:13:21.354741   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
•E0728 18:13:22.366642   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-5rxwp/test-cluster-5ksgm"
E0728 18:13:22.370186   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-m6gjm: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-m6gjm" "namespace"="default"
E0728 18:13:23.371506   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
E0728 18:13:24.383243   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-m6gjm: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-m6gjm" "namespace"="default"
•E0728 18:13:25.384068   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
E0728 18:13:25.848700   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-n5xv6\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-n5xv6" "namespace"="test-mhc-4mv9d"
E0728 18:13:26.384874   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-m6gjm: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-m6gjm" "namespace"="default"
E0728 18:13:26.849180   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-tktqs\" for machine \"test-mhc-machine-pdvbp\" in namespace \"test-mhc-4mv9d\": Cluster.cluster.x-k8s.io \"test-cluster-tktqs\" not found" "controller"="machine" "name"="test-mhc-machine-pdvbp" "namespace"="test-mhc-4mv9d"
E0728 18:13:27.396825   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
I0728 18:13:27.876013   10588 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-h7z24" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0728 18:13:27.888166   10588 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-h7z24" "namespace"="default" 
E0728 18:13:27.906896   10588 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-h7z24" "namespace"="default"
E0728 18:13:28.397659   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-m6gjm: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-m6gjm" "namespace"="default"
I0728 18:13:28.923760   10588 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-h7z24" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0728 18:13:28.923994   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-h7z24" "namespace"="default" "noderef"="id-node-1"
E0728 18:13:28.939433   10588 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-h7z24" "namespace"="default"
E0728 18:13:29.402091   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
•I0728 18:13:29.543209   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-sgnvm" "namespace"="ms-test" "creating"=2 "need"=2
I0728 18:13:29.543249   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-sgnvm" "namespace"="ms-test" 
I0728 18:13:29.560346   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-sgnvm-vcgqj\"" "machineset"="ms-sgnvm" "namespace"="ms-test" 
I0728 18:13:29.560416   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-sgnvm" "namespace"="ms-test" 
I0728 18:13:29.577132   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-sgnvm-xwz9m\"" "machineset"="ms-sgnvm" "namespace"="ms-test" 
I0728 18:13:29.666515   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-sgnvm" "namespace"="ms-test" "creating"=1 "need"=2
I0728 18:13:29.666571   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-sgnvm" "namespace"="ms-test" 
I0728 18:13:29.683892   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-sgnvm-xjtlz\"" "machineset"="ms-sgnvm" "namespace"="ms-test" 
E0728 18:13:29.913404   10588 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-sgnvm-xjtlz-xrxr8 for machine ms-test/ms-sgnvm-xjtlz: the cache is not started, can not read objects" "machineset"="ms-sgnvm" "namespace"="ms-test" 
I0728 18:13:29.939934   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-4x4kr" "machine"="test6-h7z24" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"8ff3304b-a168-45d3-93ff-3ab2f8f65e2a","apiVersion":"v1"}
E0728 18:13:29.960428   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-h7z24\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-h7z24" "namespace"="default"
E0728 18:13:30.047089   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="ms-test/test-cluster"
•I0728 18:13:30.051260   10588 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"
I0728 18:13:30.052799   10588 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0728 18:13:30.052904   10588 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"
I0728 18:13:30.054139   10588 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0728 18:13:30.054196   10588 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0728 18:13:30.055048   10588 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 ...
I0728 18:13:30.069369   10588 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"
•I0728 18:13:30.071582   10588 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"
I0728 18:13:30.072513   10588 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"
I0728 18:13:30.073132   10588 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0728 18:13:30.073166   10588 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0728 18:13:30.073707   10588 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0728 18:13:30.074947   10588 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" 
•I0728 18:13:30.204321   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0728 18:13:30.204375   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.217870   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-zpgl2-6657c7fddb-z8qj4\"" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.217950   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.230979   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-zpgl2-6657c7fddb-g5bsw\"" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.305128   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0728 18:13:30.305177   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.317917   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-zpgl2-6657c7fddb-jlmjc\"" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.318050   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.331351   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-zpgl2-6657c7fddb-cllw7\"" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
E0728 18:13:30.403212   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-m6gjm: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-m6gjm" "namespace"="default"
I0728 18:13:30.407298   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0728 18:13:30.407388   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.420660   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-6657c7fddb-lk2h8\"" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" 
I0728 18:13:30.517275   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0728 18:13:30.517320   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
I0728 18:13:30.529070   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-cdfc6fd6c-nbdjk\"" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
E0728 18:13:30.641797   10588 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-zpgl2-cdfc6fd6c-nbdjk-pvdh5 for machine md-test/md-zpgl2-cdfc6fd6c-nbdjk: the cache is not started, can not read objects" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
I0728 18:13:30.671129   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0728 18:13:30.671173   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0728 18:13:30.683187   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "machine"="md-zpgl2-6657c7fddb-jlmjc"
I0728 18:13:30.705652   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0728 18:13:30.705693   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
I0728 18:13:30.726791   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-cdfc6fd6c-dscn2\"" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
I0728 18:13:30.869684   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0728 18:13:30.869731   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0728 18:13:30.873788   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "machine"="md-zpgl2-6657c7fddb-cllw7"
E0728 18:13:30.961062   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster\" for machine \"ms-sgnvm-xwz9m\" in namespace \"ms-test\": Cluster.cluster.x-k8s.io \"test-cluster\" not found" "controller"="machine" "name"="ms-sgnvm-xwz9m" "namespace"="ms-test"
I0728 18:13:30.984375   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0728 18:13:30.984422   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
I0728 18:13:30.997277   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-cdfc6fd6c-gj85b\"" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
I0728 18:13:31.179679   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0728 18:13:31.179732   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0728 18:13:31.186657   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zpgl2-6657c7fddb" "namespace"="md-test" "machine"="md-zpgl2-6657c7fddb-lk2h8"
I0728 18:13:31.403858   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-4x4kr" "namespace"="default" "count"=1
I0728 18:13:31.403967   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-4x4kr" "namespace"="default" "descendants"="Control plane machines: test6-h7z24" "indirect descendants count"=0
E0728 18:13:31.408133   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-78b5j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-78b5j" "namespace"="default"
I0728 18:13:31.457104   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0728 18:13:31.457225   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" 
I0728 18:13:31.469994   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-74d45c49c5-5jh2p\"" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" 
I0728 18:13:31.591287   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0728 18:13:31.591334   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0728 18:13:31.597403   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "machine"="md-zpgl2-cdfc6fd6c-dscn2"
... skipping 2 lines ...
I0728 18:13:31.717562   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-74d45c49c5-xb4fz\"" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" 
I0728 18:13:31.939486   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0728 18:13:31.939529   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0728 18:13:31.946990   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "machine"="md-zpgl2-cdfc6fd6c-gj85b"
I0728 18:13:31.960733   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0728 18:13:31.960770   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" 
E0728 18:13:31.961620   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster\" for machine \"ms-sgnvm-xjtlz\" in namespace \"ms-test\": Cluster.cluster.x-k8s.io \"test-cluster\" not found" "controller"="machine" "name"="ms-sgnvm-xjtlz" "namespace"="ms-test"
I0728 18:13:31.973293   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zpgl2-74d45c49c5-cb56d\"" "machineset"="md-zpgl2-74d45c49c5" "namespace"="md-test" 
E0728 18:13:32.183653   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="md-test/test-cluster"
E0728 18:13:32.184423   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-zpgl2\" not found" "controller"="machinedeployment" "name"="md-zpgl2" "namespace"="md-test"
•

Ran 16 of 16 Specs in 16.308 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.31s)
PASS
Tearing down test suite
I0728 18:13:32.186537   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0728 18:13:32.186536   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0728 18:13:32.186657   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0728 18:13:32.186718   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0728 18:13:32.186747   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0728 18:13:32.186774   10588 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0728 18:13:32.186815   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0728 18:13:32.187959   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0
I0728 18:13:32.188020   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
E0728 18:13:32.188359   10588 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0728 18:13:32.188491   10588 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-564598875/tls.crt: no such file or directory"  
E0728 18:13:32.188894   10588 machineset_controller.go:400] controllers/MachineSet "msg"="Unable to delete Machine" "error"="an error on the server (\"apiserver is shutting down.\") has prevented the request from succeeding (delete machines.cluster.x-k8s.io md-zpgl2-cdfc6fd6c-nbdjk)" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" "machine"="md-zpgl2-cdfc6fd6c-nbdjk"
E0728 18:13:32.189268   10588 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"md-test/test-cluster\": failed to retrieve kubeconfig secret for Cluster md-test/test-cluster: Get http://127.0.0.1:42389/api/v1/namespaces/md-test/secrets/test-cluster-kubeconfig: dial tcp 127.0.0.1:42389: connect: connection refused" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
E0728 18:13:32.189786   10588 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to sync machines: an error on the server (\"apiserver is shutting down.\") has prevented the request from succeeding (delete machines.cluster.x-k8s.io md-zpgl2-cdfc6fd6c-nbdjk). failed to patch MachineSet's Status: Patch http://127.0.0.1:42389/apis/cluster.x-k8s.io/v1alpha3/namespaces/md-test/machinesets/md-zpgl2-cdfc6fd6c/status: dial tcp 127.0.0.1:42389: connect: connection refused" "machineset"="md-zpgl2-cdfc6fd6c" "namespace"="md-test" 
E0728 18:13:32.189827   10588 event.go:272] Unable to write event: 'Post http://127.0.0.1:42389/api/v1/namespaces/md-test/events: dial tcp 127.0.0.1:42389: connect: connection refused' (may retry after sleeping)
E0728 18:13:32.190280   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to sync machines: an error on the server (\"apiserver is shutting down.\") has prevented the request from succeeding (delete machines.cluster.x-k8s.io md-zpgl2-cdfc6fd6c-nbdjk). failed to patch MachineSet's Status: Patch http://127.0.0.1:42389/apis/cluster.x-k8s.io/v1alpha3/namespaces/md-test/machinesets/md-zpgl2-cdfc6fd6c/status: dial tcp 127.0.0.1:42389: connect: connection refused" "controller"="machineset" "name"="md-zpgl2-cdfc6fd6c" "namespace"="md-test"
E0728 18:13:32.238242   10588 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:42389/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1243&timeout=10s&timeoutSeconds=393&watch=true: dial tcp 127.0.0.1:42389: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	75.145s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 261 lines ...
I0728 18:12:30.110520   10831 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0728 18:12:30.129377   10831 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":{}}}
I0728 18:12:30.430106   10831 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0728 18:12:30.430173   10831 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0728 18:12:30.614318   10831 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0728 18:12:31.154510   10831 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0728 18:12:33.211245   10831 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-jqmc6/test-cluster"
•E0728 18:12:33.658668   10831 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-ncpnp/test-cluster"
•E0728 18:12:34.215901   10831 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:46567/?timeout=50ms: dial tcp 127.0.0.1:46567: connect: connection refused"  "cluster"="cluster-cache-test-6zrhz/test-cluster"
•I0728 18:12:34.440665   10831 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}}}
I0728 18:12:34.541073   10831 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0728 18:12:34.541141   10831 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•E0728 18:12:34.698001   10831 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 18:12:34.698055   10831 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-055493196/tls.crt: no such file or directory"  
E0728 18:12:34.698075   10831 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 18:12:34.698093   10831 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-055493196/tls.crt: no such file or directory"  
I0728 18:12:34.698196   10831 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0728 18:12:34.698422   10831 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0728 18:12:34.762637   10831 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:46595/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=143&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:46595: connect: connection refused


Ran 5 of 5 Specs in 16.600 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.60s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	16.726s
?   	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
I0728 18:12:43.429231   11667 controller.go:130]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.01s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0728 18:12:43.434846   11667 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
I0728 18:12:43.435453   11667 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0728 18:12:43.435618   11667 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 94 lines ...
I0728 18:13:00.920887   11667 remediation.go:248]  "msg"="etcd cluster projected after remediation of m1-unhealthy-5vhcs" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "canSafelyRemediate"=true "healthyMembers"=["node-m2-healthy-8rkpn (m2-healthy-8rkpn)","node-m3-healthy-kv42l (m3-healthy-kv42l)"] "targetQuorum"=2 "targetTotalMembers"=2 "targetUnhealthyMembers"=0 "unhealthyMembers"=[]
I0728 18:13:00.929098   11667 remediation.go:154]  "msg"="Remediating unhealthy machine" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "UnhealthyMachine"="m1-unhealthy-5vhcs"
=== RUN   TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_4_CP_(during_3_CP_rolling_upgrade)
I0728 18:13:01.068530   11667 remediation.go:195]  "msg"="etcd cluster before remediation" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "currentMembers"=["node-m1-unhealthy-fx4gx","node-m2-healthy-b2mr9","node-m3-healthy-5bx9h","node-m4-healthy-scbx4"] "currentTotalMembers"=4
I0728 18:13:01.068614   11667 remediation.go:248]  "msg"="etcd cluster projected after remediation of m1-unhealthy-fx4gx" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "canSafelyRemediate"=true "healthyMembers"=["node-m2-healthy-b2mr9 (m2-healthy-b2mr9)","node-m3-healthy-5bx9h (m3-healthy-5bx9h)","node-m4-healthy-scbx4 (m4-healthy-scbx4)"] "targetQuorum"=2 "targetTotalMembers"=3 "targetUnhealthyMembers"=0 "unhealthyMembers"=[]
I0728 18:13:01.085862   11667 remediation.go:154]  "msg"="Remediating unhealthy machine" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "UnhealthyMachine"="m1-unhealthy-fx4gx"
--- FAIL: TestReconcileUnhealthyMachines (0.89s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_are_no_unhealthy_machines (0.00s)
    --- PASS: TestReconcileUnhealthyMachines/reconcileUnhealthyMachines_return_early_if_the_machine_to_be_remediated_is_marked_for_deletion (0.00s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_desired_replicas_<=_1 (0.14s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_number_of_machines_lower_than_desired (0.06s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_a_deleting_machine (0.05s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_at_least_one_additional_unhealthy_etcd_member_on_a_3_machine_CP (0.09s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_at_least_two_additional_unhealthy_etcd_member_on_a_5_machine_CP (0.15s)
    --- FAIL: TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_2_CP_(during_1_CP_rolling_upgrade) (0.07s)
        remediation_test.go:839: 
            Expected
                <string>: WaitingForRemediation
            to equal
                <string>: RemediationInProgress
    --- PASS: TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_3_CP (0.15s)
... skipping 82 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
I0728 18:13:03.202529   11667 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
I0728 18:13:03.202751   11667 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: 1627495950
Will run 1 of 1 specs

E0728 18:13:03.227535   11667 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-ivas8x\" not found" "kubeadmControlPlane"="kcp-foo-ivas8x" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.020 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.02s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0728 18:13:03.229156   11667 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-c3h74p" "kubeadmControlPlane"="kcp-foo-c3h74p" "namespace"="test" 
I0728 18:13:05.234843   11667 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-c3h74p" "kubeadmControlPlane"="kcp-foo-c3h74p" "namespace"="test" "needRollout"=["kcp-foo-c3h74p-ghtxw"]
I0728 18:13:05.235052   11667 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-c3h74p" "kubeadmControlPlane"="kcp-foo-c3h74p" "namespace"="test" "failures"="[machine kcp-foo-c3h74p-jmsqr does not have APIServerPodHealthy condition, machine kcp-foo-c3h74p-jmsqr does not have ControllerManagerPodHealthy condition, machine kcp-foo-c3h74p-jmsqr does not have SchedulerPodHealthy condition, machine kcp-foo-c3h74p-jmsqr does not have EtcdPodHealthy condition, machine kcp-foo-c3h74p-jmsqr does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.01s)
FAIL
E0728 18:13:05.235926   11667 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 18:13:05.235966   11667 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-697667955/tls.crt: no such file or directory"  
E0728 18:13:05.235986   11667 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 18:13:05.236003   11667 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-697667955/tls.crt: no such file or directory"  
I0728 18:13:05.237045   11667 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	34.937s
I0728 18:12:41.714767   11606 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 18:12:41.714906   11606 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 18:12:41.714936   11606 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 18:12:41.714950   11606 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 18:12:41.715021   11606 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
I0728 18:12:41.715046   11606 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
... skipping 51 lines ...
==================================
Random Seed: 1627495948
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: 1627495948
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.001 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
E0728 18:12:45.715407   11606 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"  
E0728 18:12:54.038520   11606 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"  
E0728 18:13:03.024521   11606 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"  
E0728 18:13:14.154979   11606 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"  
E0728 18:13:30.628203   11606 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"  
E0728 18:13:43.636907   11606 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"  
E0728 18:14:01.284303   11606 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"  
E0728 18:14:22.207807   11606 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"  
E0728 18:14:53.224385   11606 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"  
E0728 18:15:38.381707   11606 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 383 lines ...
I0728 18:12:53.818258   11912 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" 
I0728 18:12:53.918612   11912 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0728 18:12:53.925918   11912 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0728 18:12:54.026418   11912 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0728 18:12:54.026510   11912 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0728 18:12:54.117000   11912 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-9pxxwj"} 
E0728 18:12:54.162787   11912 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"
•I0728 18:12:55.322753   11912 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-cg5t9y"} 
E0728 18:12:55.368775   11912 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"
•E0728 18:12:56.444653   11912 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
E0728 18:12:57.470408   11912 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"
•E0728 18:12:58.605228   11912 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"
•E0728 18:12:59.639937   11912 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"
E0728 18:13:00.661257   11912 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"
•I0728 18:13:00.667874   11912 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0728 18:13:00.668004   11912 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0728 18:13:00.668057   11912 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 


Ran 5 of 5 Specs in 22.209 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (22.21s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	22.271s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
... skipping 61 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0728 18:12:42.674089   12055 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.05s)
    --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.05s)
    --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestMachinePoolFinalizer
... skipping 96 lines ...
•I0728 18:12:56.432043   12055 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••I0728 18:12:56.434529   12055 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0728 18:12:56.461254   12055 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 13.697 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.70s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	13.979s
?   	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 201 lines ...
I0728 18:13:25.770513   15116 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0728 18:13:25.770698   15116 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0728 18:13:25.771877   15116 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0728 18:13:25.772301   15116 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=37171
I0728 18:13:25.772386   15116 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••I0728 18:13:26.677746   15116 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0728 18:13:26.678239   15116 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0728 18:13:26.678322   15116 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-897026523/tls.crt: no such file or directory"  


Ran 14 of 14 Specs in 8.637 seconds
SUCCESS! -- 14 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestPatch (8.64s)
=== 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.050s
FAIL
make: *** [Makefile:116: test] Error 1
+ EXIT_VALUE=2
+ set +o xtrace