This job view page is being replaced by Spyglass soon. Check out the new job view.
PRdims: 🌱 Switch to non-alpine kindest/haproxy version
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-19 23:59
Elapsed4m26s
Revision85856b0aa7204d716c3b1ccedc96d1670d4ebcab
Refs 4968

No Test Failures!


Error lines from build-log.txt

... skipping 781 lines ...
I0720 00:01:16.316432    8517 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0720 00:01:16.866498    8517 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" 
•I0720 00:01:16.879524    8517 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 14.365 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (14.37s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	65.509s
=== 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 1398 lines ...
I0720 00:00:43.795709   10533 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0720 00:00:43.795782   10533 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
I0720 00:00:43.795862   10533 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machine" "worker count"=1
I0720 00:00:43.795877   10533 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
I0720 00:00:43.797094   10533 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0720 00:00:43.799986   10533 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
2021/07/20 00:00:44 http: TLS handshake error from 127.0.0.1:59282: EOF
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0720 00:00:44.095170   10533 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"
I0720 00:00:44.105482   10533 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
... skipping 105 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0720 00:00:44.143258   10533 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
I0720 00:00:44.144887   10533 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"
E0720 00:00:44.145201   10533 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
I0720 00:00:44.145766   10533 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
--- PASS: TestReconcileInfrastructure (0.00s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestWatches
I0720 00:00:44.450464   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0720 00:00:44.551378   10533 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0720 00:00:44.559076   10533 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0720 00:00:44.559169   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0720 00:00:44.670877   10533 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0720 00:00:44.670985   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0720 00:00:44.771580   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r" "noderef"="node-1"
E0720 00:00:44.808036   10533 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0720 00:00:44.808187   10533 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0720 00:00:44.868284   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-qcdfd\" in namespace \"test-machine-watches-fw54r\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r"
E0720 00:00:45.878217   10533 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-qcdfd\" in namespace \"test-machine-watches-fw54r\", requeuing: requeue in 1s"  
E0720 00:00:45.887500   10533 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-qcdfd\" in namespace \"test-machine-watches-fw54r\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-qcdfd\" in namespace \"test-machine-watches-fw54r\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r"
--- PASS: TestWatches (1.77s)
=== 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
I0720 00:00:46.112323   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-ptm9q" "namespace"="test-machine-watches-fw54r" "count"=1
I0720 00:00:46.112389   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-ptm9q" "namespace"="test-machine-watches-fw54r" "descendants"="Worker machines: machine-created-qcdfd" "indirect descendants count"=0
I0720 00:00:46.126672   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-ptm9q" "namespace"="test-machine-watches-fw54r" "count"=1
I0720 00:00:46.126734   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-ptm9q" "namespace"="test-machine-watches-fw54r" "descendants"="Worker machines: machine-created-qcdfd" "indirect descendants count"=0
I0720 00:00:46.888000   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-ptm9q" "machine"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"a8861b5b-9eb3-492c-abc6-8f36b2d07c25","apiVersion":"v1"}
E0720 00:00:46.936912   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-qcdfd\" not found" "controller"="machine" "name"="machine-created-qcdfd" "namespace"="test-machine-watches-fw54r"
E0720 00:00:47.984822   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-bc4jb\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-fxvzs\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-fxvzs: secrets \"machine-reconcile-fxvzs-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-bc4jb" "namespace"="default"
I0720 00:00:48.985389   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fxvzs" "machine"="machine-created-bc4jb" "namespace"="default" "cause"="noderef is nil" "node"=null
I0720 00:00:49.015299   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fxvzs" "machine"="machine-created-bc4jb" "namespace"="default" "cause"="noderef is nil" "node"=null
I0720 00:00:49.047217   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fxvzs" "machine"="machine-created-bc4jb" "namespace"="default" "cause"="noderef is nil" "node"=null
E0720 00:00:49.078255   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-bc4jb\" not found" "controller"="machine" "name"="machine-created-bc4jb" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.17s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.17s)
=== 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 3 lines ...
=== RUN   TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta
I0720 00:00:49.097515   10533 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"
I0720 00:00:49.097722   10533 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
I0720 00:00:49.103335   10533 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"
I0720 00:00:49.103453   10533 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine3" "namespace"="default" 
E0720 00:00:49.104483   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-fxvzs\" not found" "controller"="cluster" "name"="machine-reconcile-fxvzs" "namespace"="default"
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner
I0720 00:00:49.107063   10533 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"
I0720 00:00:49.107164   10533 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
--- PASS: TestMachineOwnerReference (0.02s)
    --- 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.00s)
... skipping 122 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0720 00:00:49.243978   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z7r7" "namespace"="test-mhc-c9bdp" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I0720 00:00:49.262278   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0720 00:00:49.262376   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-8cdml\" not found"  "cluster"="test-mhc-c9bdp/test-cluster-8cdml"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist
E0720 00:00:49.368597   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-6z7r7\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-6z7r7\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-6z7r7" "namespace"="test-mhc-c9bdp"
I0720 00:00:50.368896   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grj9v" "namespace"="test-mhc-kwgpn" 
I0720 00:00:50.369004   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kggrj" "namespace"="test-mhc-v88jx" 
I0720 00:00:50.369034   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z7r7" "namespace"="test-mhc-c9bdp" 
I0720 00:00:50.369061   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cmfcn" "namespace"="test-mhc-mthnl" 
I0720 00:00:50.394263   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:00:50.412737   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cmfcn" "namespace"="test-mhc-mthnl" 
I0720 00:00:50.417424   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cmfcn" "namespace"="test-mhc-mthnl" 
I0720 00:00:50.502342   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cmfcn" "namespace"="test-mhc-mthnl" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
E0720 00:00:50.517583   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-mthnl/test-cluster-zmg5h"
E0720 00:00:50.517846   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-zmg5h\" not found" "controller"="cluster" "name"="test-cluster-zmg5h" "namespace"="test-mhc-mthnl"
I0720 00:00:50.628903   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zwhbh" "namespace"="test-mhc-qn7rc" 
I0720 00:00:50.642386   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:00:50.762564   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zwhbh" "namespace"="test-mhc-qn7rc" 
E0720 00:00:50.834382   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-qn7rc/test-cluster-kzs2d"
I0720 00:00:50.840776   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zwhbh" "namespace"="test-mhc-qn7rc" 
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0720 00:00:50.964292   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
inframachine created: test-mhc-machine-infra-k8d8b
I0720 00:00:50.985154   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-n26sq
I0720 00:00:51.085933   10533 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-xmgfl/test-mhc-qlbb9/test-mhc-machine-n26sq/"
node created: test-mhc-node-6mtq2
E0720 00:00:51.100186   10533 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-6mtq2"
E0720 00:00:51.100257   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6mtq2, got []"  "node"="test-mhc-node-6mtq2"
I0720 00:00:51.115673   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-n26sq" "namespace"="test-mhc-xmgfl" "noderef"="test-mhc-node-6mtq2"
inframachine created: test-mhc-machine-infra-rbk2j
machine created: test-mhc-machine-5vs9g
E0720 00:00:51.248399   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-smt7t, got []"  "node"="test-mhc-node-smt7t"
E0720 00:00:51.248399   10533 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-smt7t"
node created: test-mhc-node-smt7t
I0720 00:00:51.337391   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
I0720 00:00:51.500549   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
Cleaning up nodes, machines and infra machines.
I0720 00:00:51.508511   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
I0720 00:00:51.512656   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
I0720 00:00:51.513142   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-xmgfl/test-mhc-qlbb9/test-mhc-machine-n26sq/"
E0720 00:00:51.588597   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-fw54r/machine-reconcile-ptm9q"
I0720 00:00:51.596783   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
I0720 00:00:51.597309   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-xmgfl/test-mhc-qlbb9/test-mhc-machine-n26sq/"
I0720 00:00:51.597784   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-xmgfl/test-mhc-qlbb9/test-mhc-machine-5vs9g/"
I0720 00:00:51.636598   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-6st5q" "namespace"="test-mhc-xmgfl" "count"=2
I0720 00:00:51.636684   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6st5q" "namespace"="test-mhc-xmgfl" "descendants"="Worker machines: test-mhc-machine-n26sq,test-mhc-machine-5vs9g" "indirect descendants count"=0
I0720 00:00:51.643563   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-6st5q" "namespace"="test-mhc-xmgfl" "count"=2
I0720 00:00:51.643618   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6st5q" "namespace"="test-mhc-xmgfl" "descendants"="Worker machines: test-mhc-machine-n26sq,test-mhc-machine-5vs9g" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
inframachine created: test-mhc-machine-infra-gchlq
machine created: test-mhc-machine-lzk7h
E0720 00:00:51.759224   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-n26sq\" in namespace \"test-mhc-xmgfl\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-n26sq" "namespace"="test-mhc-xmgfl"
E0720 00:00:51.795568   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-qlbb9\" not found" "controller"="machinehealthcheck" "name"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl"
I0720 00:00:52.760063   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6st5q" "machine"="test-mhc-machine-5vs9g" "namespace"="test-mhc-xmgfl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-smt7t"}
I0720 00:00:52.795890   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
E0720 00:00:52.821381   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5vs9g\" not found" "controller"="machine" "name"="test-mhc-machine-5vs9g" "namespace"="test-mhc-xmgfl"
I0720 00:00:52.821940   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:00:52.945869   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlbb9" "namespace"="test-mhc-xmgfl" 
I0720 00:00:52.945977   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:52.954029   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:52.955155   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:52.957178   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
... skipping 416 lines ...
I0720 00:00:53.819128   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.821533   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.826989   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.828741   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.835629   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6st5q" "machine"="test-mhc-machine-n26sq" "namespace"="test-mhc-xmgfl" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-6mtq2","uid":"dd50f878-4d82-4c9c-a600-9dd540d58cb9","apiVersion":"v1"}
I0720 00:00:53.839776   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.840049   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-lzk7h/"
node created: test-mhc-node-w5ksl
E0720 00:00:53.847409   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-w5ksl, got []"  "node"="test-mhc-node-w5ksl"
E0720 00:00:53.847698   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-w5ksl, got []"  "node"="test-mhc-node-w5ksl"
I0720 00:00:53.854170   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.854476   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-lzk7h/"
I0720 00:00:53.858093   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
inframachine created: test-mhc-machine-infra-lclnk
machine created: test-mhc-machine-8l9hq
I0720 00:00:53.881914   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.889485   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.890505   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.892536   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.894641   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.897708   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.900012   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.902014   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
E0720 00:00:53.903115   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-n26sq\" not found" "controller"="machine" "name"="test-mhc-machine-n26sq" "namespace"="test-mhc-xmgfl"
I0720 00:00:53.904023   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.906006   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.907964   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.909974   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.911962   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:53.913939   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
... skipping 415 lines ...
I0720 00:00:54.935543   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.938012   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.939596   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.940597   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.943953   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.952489   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.955457   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-8l9hq/"
I0720 00:00:54.969003   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.969699   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-8l9hq/"
I0720 00:00:54.980800   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.981256   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-8l9hq/"
node created: test-mhc-node-mhsgr
E0720 00:00:54.985803   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mhsgr, got []"  "node"="test-mhc-node-mhsgr"
E0720 00:00:54.987927   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mhsgr, got []"  "node"="test-mhc-node-mhsgr"
I0720 00:00:54.991841   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:54.992272   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-8l9hq/"
I0720 00:00:54.996709   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
inframachine created: test-mhc-machine-infra-k79jh
machine created: test-mhc-machine-47k5f
E0720 00:00:55.120427   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xw6pq, got []"  "node"="test-mhc-node-xw6pq"
E0720 00:00:55.120652   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xw6pq, got []"  "node"="test-mhc-node-xw6pq"
node created: test-mhc-node-xw6pq
I0720 00:00:55.142714   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:55.143329   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-47k5f/test-mhc-node-xw6pq"
I0720 00:00:55.328795   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:55.329542   10533 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-6trdc/test-mhc-28hbx/test-mhc-machine-47k5f/test-mhc-node-xw6pq"
Cleaning up nodes, machines and infra machines.
I0720 00:00:55.352798   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-28hbx" "namespace"="test-mhc-6trdc" 
I0720 00:00:55.353353   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-6trdc/test-mhc-28hbx/test-mhc-machine-47k5f/"
Cleaning up nodes, machines and infra machines.
E0720 00:00:55.383753   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-47k5f\" in namespace \"test-mhc-6trdc\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-47k5f" "namespace"="test-mhc-6trdc"
I0720 00:00:55.411537   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-6cg5k" "namespace"="test-mhc-6trdc" "count"=3
I0720 00:00:55.411624   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6cg5k" "namespace"="test-mhc-6trdc" "descendants"="Worker machines: test-mhc-machine-47k5f,test-mhc-machine-lzk7h,test-mhc-machine-8l9hq" "indirect descendants count"=0
I0720 00:00:55.417312   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-6cg5k" "namespace"="test-mhc-6trdc" "count"=3
I0720 00:00:55.417386   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6cg5k" "namespace"="test-mhc-6trdc" "descendants"="Worker machines: test-mhc-machine-lzk7h,test-mhc-machine-8l9hq,test-mhc-machine-47k5f" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
inframachine created: test-mhc-machine-infra-lvtnr
... skipping 6 lines ...
I0720 00:00:55.747824   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:55.788841   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:55.869878   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:56.030863   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:56.351887   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:56.384440   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6cg5k" "machine"="test-mhc-machine-47k5f" "namespace"="test-mhc-6trdc" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xw6pq"}
E0720 00:00:56.442554   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-47k5f\" not found" "controller"="machine" "name"="test-mhc-machine-47k5f" "namespace"="test-mhc-6trdc"
E0720 00:00:56.657946   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-xmgfl/test-cluster-6st5q"
I0720 00:00:56.994137   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:57.444057   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6cg5k" "machine"="test-mhc-machine-lzk7h" "namespace"="test-mhc-6trdc" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-w5ksl"}
E0720 00:00:57.505968   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-lzk7h\" not found" "controller"="machine" "name"="test-mhc-machine-lzk7h" "namespace"="test-mhc-6trdc"
I0720 00:00:58.275255   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:58.506529   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6cg5k" "machine"="test-mhc-machine-8l9hq" "namespace"="test-mhc-6trdc" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-mhsgr"}
E0720 00:00:58.547042   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-8l9hq\" not found" "controller"="machine" "name"="test-mhc-machine-8l9hq" "namespace"="test-mhc-6trdc"
I0720 00:00:59.555208   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.560001   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.579222   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
E0720 00:00:59.583858   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k8v6g, got []"  "node"="test-mhc-node-k8v6g"
E0720 00:00:59.584051   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k8v6g, got []"  "node"="test-mhc-node-k8v6g"
node created: test-mhc-node-k8v6g
I0720 00:00:59.589700   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.596195   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
inframachine created: test-mhc-machine-infra-jm9kv
machine created: test-mhc-machine-rcvz9
I0720 00:00:59.626610   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
... skipping 3 lines ...
I0720 00:00:59.663198   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.669501   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.679445   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.683720   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.709373   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.712284   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
E0720 00:00:59.724247   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-74s9j, got []"  "node"="test-mhc-node-74s9j"
E0720 00:00:59.724525   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-74s9j, got []"  "node"="test-mhc-node-74s9j"
node created: test-mhc-node-74s9j
I0720 00:00:59.726355   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-rcvz9" "namespace"="test-mhc-69lc7" "noderef"="test-mhc-node-74s9j"
I0720 00:00:59.733061   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
inframachine created: test-mhc-machine-infra-7kxk9
I0720 00:00:59.745446   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
machine created: test-mhc-machine-nlt6x
... skipping 4 lines ...
I0720 00:00:59.876063   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.890204   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.904027   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.908361   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.943064   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
node created: test-mhc-node-tsgsg
E0720 00:00:59.958303   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tsgsg, got []"  "node"="test-mhc-node-tsgsg"
E0720 00:00:59.958563   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tsgsg, got []"  "node"="test-mhc-node-tsgsg"
I0720 00:00:59.959863   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:00:59.969212   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
Cleaning up nodes, machines and infra machines.
I0720 00:00:59.984763   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:01:00.008894   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
Cleaning up nodes, machines and infra machines.
E0720 00:01:00.026120   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-rcvz9\" in namespace \"test-mhc-69lc7\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-rcvz9" "namespace"="test-mhc-69lc7"
I0720 00:01:00.042531   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-95s92" "namespace"="test-mhc-69lc7" "count"=3
I0720 00:01:00.042617   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-95s92" "namespace"="test-mhc-69lc7" "descendants"="Worker machines: test-mhc-machine-nlt6x,test-mhc-machine-2lq2w,test-mhc-machine-rcvz9" "indirect descendants count"=0
I0720 00:01:00.048145   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-95s92" "namespace"="test-mhc-69lc7" "count"=3
I0720 00:01:00.048219   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-95s92" "namespace"="test-mhc-69lc7" "descendants"="Worker machines: test-mhc-machine-2lq2w,test-mhc-machine-rcvz9,test-mhc-machine-nlt6x" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
inframachine created: test-mhc-machine-infra-kvwkr
machine created: test-mhc-machine-4fq55
I0720 00:01:00.202083   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:00.221024   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:01:00.257842   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:01:00.258073   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
E0720 00:01:00.430791   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-6trdc/test-cluster-6cg5k"
I0720 00:01:01.026667   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-95s92" "machine"="test-mhc-machine-nlt6x" "namespace"="test-mhc-69lc7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-tsgsg"}
E0720 00:01:01.068220   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-nlt6x\" not found" "controller"="machine" "name"="test-mhc-machine-nlt6x" "namespace"="test-mhc-69lc7"
I0720 00:01:02.070466   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-95s92" "machine"="test-mhc-machine-rcvz9" "namespace"="test-mhc-69lc7" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-74s9j","uid":"36377ed9-e419-46d4-929f-0a4c2a30dc56","apiVersion":"v1"}
E0720 00:01:02.114894   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-rcvz9\" not found" "controller"="machine" "name"="test-mhc-machine-rcvz9" "namespace"="test-mhc-69lc7"
I0720 00:01:03.115395   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-95s92" "machine"="test-mhc-machine-2lq2w" "namespace"="test-mhc-69lc7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-k8v6g"}
E0720 00:01:03.156718   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2lq2w\" not found" "controller"="machine" "name"="test-mhc-machine-2lq2w" "namespace"="test-mhc-69lc7"
I0720 00:01:04.165387   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.170583   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.191837   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.202792   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.208905   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
E0720 00:01:04.211775   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-stjj8, got []"  "node"="test-mhc-node-stjj8"
E0720 00:01:04.212028   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-stjj8, got []"  "node"="test-mhc-node-stjj8"
node created: test-mhc-node-stjj8
I0720 00:01:04.215014   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-4fq55" "namespace"="test-mhc-7br8t" "noderef"="test-mhc-node-stjj8"
E0720 00:01:04.220221   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-stjj8, got []"  "node"="test-mhc-node-stjj8"
E0720 00:01:04.220270   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-stjj8, got []"  "node"="test-mhc-node-stjj8"
E0720 00:01:04.220432   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-stjj8, got []"  "node"="test-mhc-node-stjj8"
E0720 00:01:04.220464   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-stjj8, got []"  "node"="test-mhc-node-stjj8"
I0720 00:01:04.222252   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
inframachine created: test-mhc-machine-infra-gwxkf
machine created: test-mhc-machine-s9244
I0720 00:01:04.246842   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.258888   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.387769   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.396801   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.424340   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.432446   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
node created: test-mhc-node-gdfj9
E0720 00:01:04.441090   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gdfj9, got []"  "node"="test-mhc-node-gdfj9"
E0720 00:01:04.443336   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gdfj9, got []"  "node"="test-mhc-node-gdfj9"
I0720 00:01:04.452734   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.453199   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-s9244" "namespace"="test-mhc-7br8t" "noderef"="test-mhc-node-gdfj9"
inframachine created: test-mhc-machine-infra-nn64g
I0720 00:01:04.472820   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.474348   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.493702   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
... skipping 7 lines ...
I0720 00:01:04.594842   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.603690   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
Cleaning up nodes, machines and infra machines.
I0720 00:01:04.616846   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.635915   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.647765   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.648325   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7br8t/test-mhc-r6cmb/test-mhc-machine-4fq55/"
I0720 00:01:04.653004   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xrpsz" "machine"="test-mhc-machine-vlrqf" "namespace"="test-mhc-7br8t" "cause"="noderef is nil" "node"=null
I0720 00:01:04.728757   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:04.730568   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7br8t/test-mhc-r6cmb/test-mhc-machine-4fq55/"
I0720 00:01:04.731519   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7br8t/test-mhc-r6cmb/test-mhc-machine-s9244/"
I0720 00:01:04.748982   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-xrpsz" "namespace"="test-mhc-7br8t" "count"=3
I0720 00:01:04.749071   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xrpsz" "namespace"="test-mhc-7br8t" "descendants"="Worker machines: test-mhc-machine-4fq55,test-mhc-machine-s9244,test-mhc-machine-vlrqf" "indirect descendants count"=0
I0720 00:01:04.758792   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-xrpsz" "namespace"="test-mhc-7br8t" "count"=3
I0720 00:01:04.758856   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xrpsz" "namespace"="test-mhc-7br8t" "descendants"="Worker machines: test-mhc-machine-4fq55,test-mhc-machine-s9244,test-mhc-machine-vlrqf" "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
E0720 00:01:04.775324   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-r6cmb\" not found" "controller"="machinehealthcheck" "name"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t"
E0720 00:01:04.783168   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vlrqf\" not found" "controller"="machine" "name"="test-mhc-machine-vlrqf" "namespace"="test-mhc-7br8t"
inframachine created: test-mhc-machine-infra-7cx69
machine created: test-mhc-machine-x8d86
E0720 00:01:05.061268   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-69lc7/test-cluster-95s92"
I0720 00:01:05.775613   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r6cmb" "namespace"="test-mhc-7br8t" 
I0720 00:01:05.775713   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q9qc6" "namespace"="test-mhc-69lc7" 
I0720 00:01:05.775741   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.784098   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xrpsz" "machine"="test-mhc-machine-4fq55" "namespace"="test-mhc-7br8t" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-stjj8","uid":"0bbaff65-9c2a-46c9-b181-388d2a41a055","apiVersion":"v1"}
I0720 00:01:05.792056   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:01:05.818627   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.828441   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.829584   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.831680   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.833472   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.835251   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.837126   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.843500   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
E0720 00:01:05.845352   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-4fq55\" not found" "controller"="machine" "name"="test-mhc-machine-4fq55" "namespace"="test-mhc-7br8t"
I0720 00:01:05.847104   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.849987   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.853712   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.860028   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.863307   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:05.865271   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
... skipping 470 lines ...
I0720 00:01:06.893059   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.897138   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.899521   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.901535   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.903830   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.906049   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
E0720 00:01:06.906460   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-s9244\" not found" "controller"="machine" "name"="test-mhc-machine-s9244" "namespace"="test-mhc-7br8t"
I0720 00:01:06.907840   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.909542   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.911164   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.913044   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.915072   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:06.916880   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
... skipping 413 lines ...
I0720 00:01:07.917162   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.918850   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.920335   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.920894   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.922355   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.923662   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.923912   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:07.934736   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.935041   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:07.943411   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.943740   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:07.953767   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.954137   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:07.964383   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.964750   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:07.976644   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.976966   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:07.982555   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:07.982873   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
E0720 00:01:08.020975   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dbwql, got []"  "node"="test-mhc-node-dbwql"
E0720 00:01:08.021139   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dbwql, got []"  "node"="test-mhc-node-dbwql"
node created: test-mhc-node-dbwql
I0720 00:01:08.023741   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-x8d86" "namespace"="test-mhc-t59p2" "noderef"="test-mhc-node-dbwql"
E0720 00:01:08.027094   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dbwql, got []"  "node"="test-mhc-node-dbwql"
E0720 00:01:08.027142   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dbwql, got []"  "node"="test-mhc-node-dbwql"
E0720 00:01:08.027325   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dbwql, got []"  "node"="test-mhc-node-dbwql"
E0720 00:01:08.027373   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-dbwql, got []"  "node"="test-mhc-node-dbwql"
I0720 00:01:08.034107   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.034426   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:08.040275   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.059393   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.073103   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.075116   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/test-mhc-node-dbwql"
I0720 00:01:08.245294   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
Cleaning up nodes, machines and infra machines.
I0720 00:01:08.245666   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/test-mhc-node-dbwql"
I0720 00:01:08.247471   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.247818   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/test-mhc-node-dbwql"
I0720 00:01:08.250745   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.251075   10533 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-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/test-mhc-node-dbwql"
I0720 00:01:08.252486   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.252777   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:08.268895   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.269236   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:08.271218   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.271872   10533 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-t59p2/test-mhc-wfzwh/test-mhc-machine-x8d86/"
I0720 00:01:08.280372   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-r2xfb" "namespace"="test-mhc-t59p2" "count"=1
I0720 00:01:08.280530   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r2xfb" "namespace"="test-mhc-t59p2" "descendants"="Worker machines: test-mhc-machine-x8d86" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0720 00:01:08.292349   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wfzwh" "namespace"="test-mhc-t59p2" 
I0720 00:01:08.311748   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-r2xfb" "namespace"="test-mhc-t59p2" "count"=1
I0720 00:01:08.311811   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r2xfb" "namespace"="test-mhc-t59p2" "descendants"="Worker machines: test-mhc-machine-x8d86" "indirect descendants count"=0
I0720 00:01:08.431521   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" "creating"=1 "need"=1
I0720 00:01:08.431576   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:08.446573   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-zctwv-wmjpv\"" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
E0720 00:01:08.446678   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-x8d86\" in namespace \"test-mhc-t59p2\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-x8d86" "namespace"="test-mhc-t59p2"
I0720 00:01:08.521461   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:08.540550   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:01:08.556488   10533 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:08.567954   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:08.576168   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:09.448143   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-r2xfb" "machine"="test-mhc-machine-x8d86" "namespace"="test-mhc-t59p2" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-dbwql","uid":"21a6e2dc-0c1d-4f5b-90d5-2d6f5064c521","apiVersion":"v1"}
E0720 00:01:09.495590   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x8d86\" not found" "controller"="machine" "name"="test-mhc-machine-x8d86" "namespace"="test-mhc-t59p2"
I0720 00:01:09.568131   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
E0720 00:01:09.781035   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-7br8t/test-cluster-xrpsz"
I0720 00:01:10.503268   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.504135   10533 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.508966   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.509495   10533 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.517910   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.517957   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
... skipping 4 lines ...
I0720 00:01:10.538522   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.538563   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:10.569170   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:11.539787   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:11.539833   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.000674   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.001137   10533 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-q2nxg/test-mhc-xzpz4/mhc-ms-zctwv-wmjpv/"
I0720 00:01:12.008689   10533 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.015978   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.016325   10533 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-q2nxg/test-mhc-xzpz4/mhc-ms-zctwv-wmjpv/"
I0720 00:01:12.021258   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.021302   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.031006   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.031379   10533 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-q2nxg/test-mhc-xzpz4/mhc-ms-zctwv-wmjpv/"
I0720 00:01:12.032177   10533 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.041453   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.041497   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.064726   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-smhtq" "namespace"="test-mhc-q2nxg" "count"=1
I0720 00:01:12.064786   10533 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-smhtq" "namespace"="test-mhc-q2nxg" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-zctwv"
I0720 00:01:12.069121   10533 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" "machine"="mhc-ms-zctwv-wmjpv"
I0720 00:01:12.071922   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-smhtq" "namespace"="test-mhc-q2nxg" "descendants"="Machine sets: mhc-ms-zctwv;Worker machines: mhc-ms-zctwv-wmjpv" "indirect descendants count"=1
I0720 00:01:12.073241   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xzpz4" "namespace"="test-mhc-q2nxg" 
I0720 00:01:12.074999   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-smhtq" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" "cause"="cluster is being deleted" "node"=null
I0720 00:01:12.091073   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-smhtq" "namespace"="test-mhc-q2nxg" "descendants"="Worker machines: mhc-ms-zctwv-wmjpv" "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
E0720 00:01:12.098785   10533 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-zctwv\" not found" "machineset"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg" 
E0720 00:01:12.098850   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-zctwv\" not found" "controller"="machineset" "name"="mhc-ms-zctwv" "namespace"="test-mhc-q2nxg"
I0720 00:01:12.264099   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
inframachine created: test-mhc-machine-infra-r6tl7
machine created: test-mhc-machine-9l6t6
I0720 00:01:12.290978   10533 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0720 00:01:12.314706   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.324838   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.331003   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.332585   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.336508   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.337625   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.338198   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-smhtq" "machine"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg" "cause"="cluster is being deleted" "node"=null
E0720 00:01:12.387054   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-zctwv-wmjpv\" not found" "controller"="machine" "name"="mhc-ms-zctwv-wmjpv" "namespace"="test-mhc-q2nxg"
node created: test-mhc-node-7jgwr
E0720 00:01:12.393083   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7jgwr, got []"  "node"="test-mhc-node-7jgwr"
E0720 00:01:12.393133   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7jgwr, got []"  "node"="test-mhc-node-7jgwr"
E0720 00:01:12.393283   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7jgwr, got []"  "node"="test-mhc-node-7jgwr"
I0720 00:01:12.417686   10533 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-9l6t6" "target"="test-mhc-t9gss/test-mhc-p4qv2/test-mhc-machine-9l6t6/"
I0720 00:01:12.430762   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.453105   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.459141   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.469441   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.474479   10533 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-9l6t6" "target"="test-mhc-t9gss/test-mhc-p4qv2/test-mhc-machine-9l6t6/test-mhc-node-7jgwr"
I0720 00:01:12.492448   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.495536   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
Cleaning up nodes, machines and infra machines.
I0720 00:01:12.507632   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.511631   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p4qv2" "namespace"="test-mhc-t9gss" 
I0720 00:01:12.520052   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-fkqbw" "namespace"="test-mhc-t9gss" "descendants"="Worker machines: test-mhc-machine-9l6t6" "indirect descendants count"=1
... skipping 310 lines ...
I0720 00:01:13.307485   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.309799   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.311909   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.316172   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.319582   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.322177   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
E0720 00:01:13.323016   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-t59p2/test-cluster-r2xfb"
I0720 00:01:13.324857   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.326634   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.328457   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.330251   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.332119   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.334224   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
... skipping 38 lines ...
I0720 00:01:13.416572   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.418373   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.420174   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.421962   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.423608   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.425389   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
E0720 00:01:13.426135   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9l6t6\" not found" "controller"="machine" "name"="test-mhc-machine-9l6t6" "namespace"="test-mhc-t9gss"
I0720 00:01:13.430956   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.432864   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.434671   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.436485   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.438260   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:13.439946   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
... skipping 437 lines ...
I0720 00:01:14.436808   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.438559   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.439204   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.440278   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.442021   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.444244   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.447637   10533 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-gwnh6" "target"="test-mhc-zj9lr/test-mhc-jh8jq/test-mhc-machine-gwnh6/"
E0720 00:01:14.521793   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-zj76l, got []"  "node"="test-mhc-node-zj76l"
E0720 00:01:14.522081   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-zj76l, got []"  "node"="test-mhc-node-zj76l"
E0720 00:01:14.522370   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-zj76l, got []"  "node"="test-mhc-node-zj76l"
node created: test-mhc-node-zj76l
I0720 00:01:14.582007   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.610303   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.617040   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.631279   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.633812   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.646474   10533 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-gwnh6" "target"="test-mhc-zj9lr/test-mhc-jh8jq/test-mhc-machine-gwnh6/test-mhc-node-zj76l"
I0720 00:01:14.670935   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.681293   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.735922   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
Cleaning up nodes, machines and infra machines.
I0720 00:01:14.748267   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
I0720 00:01:14.752597   10533 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-gwnh6" "target"="test-mhc-zj9lr/test-mhc-jh8jq/test-mhc-machine-gwnh6/"
I0720 00:01:14.760386   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6jzhs" "machine"="test-mhc-machine-gwnh6" "namespace"="test-mhc-zj9lr" "cause"="no control plane members" "node"={"name":"test-mhc-node-zj76l"}
I0720 00:01:14.779321   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-6jzhs" "namespace"="test-mhc-zj9lr" "count"=1
I0720 00:01:14.779463   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6jzhs" "namespace"="test-mhc-zj9lr" "descendants"="Worker machines: test-mhc-machine-gwnh6" "indirect descendants count"=0
I0720 00:01:14.784775   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-6jzhs" "namespace"="test-mhc-zj9lr" "count"=1
I0720 00:01:14.784835   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6jzhs" "namespace"="test-mhc-zj9lr" "descendants"="Worker machines: test-mhc-machine-gwnh6" "indirect descendants count"=0
--- PASS: TestMachineHealthCheck_Reconcile (25.58s)
... skipping 15 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.43s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.27s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0720 00:01:14.798760   10533 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.01s)
    --- 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
E0720 00:01:14.807162   10533 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
E0720 00:01:14.810446   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gwnh6\" not found" "controller"="machine" "name"="test-mhc-machine-gwnh6" "namespace"="test-mhc-zj9lr"
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace
--- PASS: TestMachineToMachineHealthCheck (0.01s)
    --- 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
E0720 00:01:14.811993   10533 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0720 00:01:14.812264   10533 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
E0720 00:01:14.812988   10533 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
I0720 00:01:14.816302   10533 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0720 00:01:14.817417   10533 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0720 00:01:14.819414   10533 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
E0720 00:01:14.840427   10533 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
E0720 00:01:14.847100   10533 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 59 lines ...
================================
Random Seed: 1626739232
Will run 16 of 16 specs

I0720 00:01:14.958145   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-jq2bf" "namespace"="ms-test" "creating"=2 "need"=2
I0720 00:01:14.958194   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-jq2bf" "namespace"="ms-test" 
E0720 00:01:14.966039   10533 machinehealthcheck_controller.go:167] controllers/MachineHealthCheck "msg"="Failed to reconcile MachineHealthCheck" "error"="failed to patch unhealthy machine status for machine: test-mhc-zj9lr/test-mhc-machine-gwnh6: [Machine.cluster.x-k8s.io \"test-mhc-machine-gwnh6\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-gwnh6\" not found]" "cluster"="test-cluster-6jzhs" 
E0720 00:01:14.972337   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[failed to patch unhealthy machine status for machine: test-mhc-zj9lr/test-mhc-machine-gwnh6: [Machine.cluster.x-k8s.io \"test-mhc-machine-gwnh6\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-gwnh6\" not found], machinehealthchecks.cluster.x-k8s.io \"test-mhc-jh8jq\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr"
I0720 00:01:14.972898   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-jq2bf-tt88v\"" "machineset"="ms-jq2bf" "namespace"="ms-test" 
I0720 00:01:14.972965   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-jq2bf" "namespace"="ms-test" 
I0720 00:01:14.989546   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-jq2bf-l74bz\"" "machineset"="ms-jq2bf" "namespace"="ms-test" 
I0720 00:01:15.146126   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-jq2bf" "namespace"="ms-test" "creating"=1 "need"=2
I0720 00:01:15.146179   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-jq2bf" "namespace"="ms-test" 
I0720 00:01:15.241484   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-jq2bf-kpvnm\"" "machineset"="ms-jq2bf" "namespace"="ms-test" 
E0720 00:01:15.345387   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.345573   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.345734   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.449727   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.449779   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.449727   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.449812   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.449859   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.449910   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-kpvnm-rj8c5, got []"  "node"="ms-jq2bf-kpvnm-rj8c5"
E0720 00:01:15.492641   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.492641   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.492746   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.494775   10533 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-jq2bf-kpvnm-rj8c5 for machine ms-test/ms-jq2bf-kpvnm: the cache is not started, can not read objects" "machineset"="ms-jq2bf" "namespace"="ms-test" 
E0720 00:01:15.495842   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.495884   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.496121   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.496153   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.496470   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
E0720 00:01:15.496503   10533 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-jq2bf-l74bz-799vv, got []"  "node"="ms-jq2bf-l74bz-799vv"
I0720 00:01:15.620937   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-jq2bf-kpvnm,ms-jq2bf-l74bz" "indirect descendants count"=2
I0720 00:01:15.624939   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-jq2bf-kpvnm,ms-jq2bf-l74bz" "indirect descendants count"=2
••E0720 00:01:15.773964   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-dwdr7\" not found" "controller"="cluster" "name"="test1-dwdr7" "namespace"="default"
I0720 00:01:15.972554   10533 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jh8jq" "namespace"="test-mhc-zj9lr" 
•I0720 00:01:16.953834   10533 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-qb6hp" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0720 00:01:17.099703   10533 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-qb6hp" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0720 00:01:17.108057   10533 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-qb6hp" "namespace"="default"
E0720 00:01:18.133060   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-q2nxg/test-cluster-smhtq"
E0720 00:01:18.137430   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
•E0720 00:01:19.150241   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-t9gss/test-cluster-fkqbw"
E0720 00:01:19.168916   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-rgvql\" not found" "controller"="cluster" "name"="test3-rgvql" "namespace"="default"
E0720 00:01:20.169761   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
E0720 00:01:21.198827   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
E0720 00:01:21.199203   10533 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-zj9lr/test-cluster-6jzhs"
•I0720 00:01:22.199447   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-jq2bf-kpvnm,ms-jq2bf-l74bz" "indirect descendants count"=2
E0720 00:01:22.204583   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-xbkzb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-xbkzb" "namespace"="default"
E0720 00:01:23.205371   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
E0720 00:01:24.216988   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-xbkzb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-xbkzb" "namespace"="default"
•E0720 00:01:25.217772   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
E0720 00:01:26.218615   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-xbkzb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-xbkzb" "namespace"="default"
E0720 00:01:27.229703   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
I0720 00:01:27.309261   10533 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-qzz9k" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0720 00:01:27.332756   10533 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-qzz9k" "namespace"="default" 
E0720 00:01:27.360344   10533 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-qzz9k" "namespace"="default"
E0720 00:01:28.230484   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-xbkzb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-xbkzb" "namespace"="default"
I0720 00:01:28.395989   10533 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-qzz9k" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0720 00:01:28.396302   10533 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-qzz9k" "namespace"="default" "noderef"="id-node-1"
E0720 00:01:28.421219   10533 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-qzz9k" "namespace"="default"
I0720 00:01:29.231063   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-jq2bf-kpvnm,ms-jq2bf-l74bz" "indirect descendants count"=2
E0720 00:01:29.236139   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"

------------------------------
• [SLOW TEST:5.057 seconds]
Cluster Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/controllers/cluster_controller_test.go:45
  Should successfully set Status.ControlPlaneInitialized on the cluster object if controlplane is ready
... skipping 2 lines ...
I0720 00:01:29.382347   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0720 00:01:29.382401   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:29.394034   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-kwwwr-6657c7fddb-jn25d\"" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:29.394088   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:29.419403   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-kwwwr-6657c7fddb-fhck8\"" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:29.421632   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fp592" "machine"="test6-qzz9k" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"465f353b-9527-4bd7-87cf-bf56f7d499a0","apiVersion":"v1"}
E0720 00:01:29.455181   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-qzz9k\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-qzz9k" "namespace"="default"
E0720 00:01:29.474908   10533 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"md-kwwwr-6657c7fddb\" not found" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
E0720 00:01:29.475003   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"md-kwwwr-6657c7fddb\" not found" "controller"="machineset" "name"="md-kwwwr-6657c7fddb" "namespace"="md-test"
E0720 00:01:30.236900   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-xbkzb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-xbkzb" "namespace"="default"
I0720 00:01:30.479729   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "creating"=3 "need"=3
I0720 00:01:30.479885   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 3, ( spec.replicas(3) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:30.503652   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fp592" "machine"="test6-qzz9k" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"465f353b-9527-4bd7-87cf-bf56f7d499a0","apiVersion":"v1"}
E0720 00:01:30.504586   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-qzz9k\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-qzz9k" "namespace"="default"
I0720 00:01:30.505015   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 3 with name \"md-kwwwr-6657c7fddb-czjv6\"" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:30.505089   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 3, ( spec.replicas(3) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:30.516009   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 3 with name \"md-kwwwr-6657c7fddb-l86hr\"" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:30.516064   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 3 of 3, ( spec.replicas(3) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:30.526790   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 3 of 3 with name \"md-kwwwr-6657c7fddb-99mhr\"" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" 
I0720 00:01:30.541403   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0720 00:01:30.541455   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
I0720 00:01:30.551684   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-kwwwr-cdfc6fd6c-cfcp5\"" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
E0720 00:01:30.728798   10533 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-kwwwr-cdfc6fd6c-cfcp5-7d8tj for machine md-test/md-kwwwr-cdfc6fd6c-cfcp5: the cache is not started, can not read objects" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
I0720 00:01:30.763834   10533 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0720 00:01:30.763889   10533 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0720 00:01:30.769786   10533 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "machine"="md-kwwwr-6657c7fddb-czjv6"
I0720 00:01:30.797028   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0720 00:01:30.797078   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
I0720 00:01:30.818413   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-kwwwr-cdfc6fd6c-b5vnz\"" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
... skipping 2 lines ...
I0720 00:01:31.002858   10533 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "machine"="md-kwwwr-6657c7fddb-l86hr"
I0720 00:01:31.113963   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0720 00:01:31.114017   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
I0720 00:01:31.125679   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-kwwwr-cdfc6fd6c-xxdhf\"" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" 
I0720 00:01:31.237451   10533 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-fp592" "namespace"="default" "count"=1
I0720 00:01:31.237531   10533 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-fp592" "namespace"="default" "descendants"="Control plane machines: test6-qzz9k" "indirect descendants count"=0
E0720 00:01:31.258348   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-qb6hp: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-qb6hp" "namespace"="default"
I0720 00:01:31.314888   10533 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0720 00:01:31.314941   10533 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0720 00:01:31.319547   10533 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-kwwwr-6657c7fddb" "namespace"="md-test" "machine"="md-kwwwr-6657c7fddb-99mhr"
I0720 00:01:31.519857   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-kwwwr-6657c7fddb-jn25d" "namespace"="md-test" 
I0720 00:01:31.519898   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-kwwwr-6657c7fddb-jn25d" "namespace"="md-test" 
I0720 00:01:31.544258   10533 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-kwwwr-6657c7fddb-fhck8" "namespace"="md-test" 
I0720 00:01:31.544296   10533 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-kwwwr-6657c7fddb-fhck8" "namespace"="md-test" 
I0720 00:01:31.556893   10533 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fp592" "machine"="test6-qzz9k" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"465f353b-9527-4bd7-87cf-bf56f7d499a0","apiVersion":"v1"}
E0720 00:01:31.557665   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-qzz9k\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-qzz9k" "namespace"="default"
I0720 00:01:31.592861   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0720 00:01:31.592905   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-kwwwr-74d45c49c5" "namespace"="md-test" 
I0720 00:01:31.606443   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-kwwwr-74d45c49c5-654dt\"" "machineset"="md-kwwwr-74d45c49c5" "namespace"="md-test" 
I0720 00:01:31.758171   10533 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0720 00:01:31.758222   10533 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0720 00:01:31.763212   10533 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "machine"="md-kwwwr-cdfc6fd6c-b5vnz"
... skipping 3 lines ...
I0720 00:01:31.902194   10533 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0720 00:01:31.902247   10533 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0720 00:01:31.910471   10533 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "machine"="md-kwwwr-cdfc6fd6c-xxdhf"
I0720 00:01:31.953816   10533 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-kwwwr-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0720 00:01:31.953883   10533 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-kwwwr-74d45c49c5" "namespace"="md-test" 
I0720 00:01:31.965182   10533 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-kwwwr-74d45c49c5-jpj8l\"" "machineset"="md-kwwwr-74d45c49c5" "namespace"="md-test" 
E0720 00:01:32.056917   10533 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-kwwwr\" not found" "controller"="machinedeployment" "name"="md-kwwwr" "namespace"="md-test"
I0720 00:01:32.059410   10533 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0
I0720 00:01:32.059448   10533 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
•I0720 00:01:32.062539   10533 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"
I0720 00:01:32.063531   10533 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-kwwwr-cdfc6fd6c" "namespace"="md-test" "machine"="md-kwwwr-cdfc6fd6c-cfcp5"
I0720 00:01:32.063796   10533 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0720 00:01:32.063849   10533 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 16 lines ...
I0720 00:01:32.075633   10533 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"
•I0720 00:01:32.077063   10533 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"
I0720 00:01:32.077924   10533 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"
I0720 00:01:32.078593   10533 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0720 00:01:32.078683   10533 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0720 00:01:32.079331   10533 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0720 00:01:32.080688   10533 machine_controller.go:494]  "msg"="Error creating a remote client while deleting Machine, won't retry" "error"="failed to create REST configuration for Cluster default/test-cluster: invalid configuration: no configuration has been provided" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" 
•

Ran 16 of 16 Specs in 17.230 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (17.23s)
PASS
Tearing down test suite
I0720 00:01:32.082287   10533 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0720 00:01:32.082351   10533 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0720 00:01:32.082360   10533 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0720 00:01:32.082397   10533 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0720 00:01:32.082419   10533 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0720 00:01:32.082438   10533 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0720 00:01:32.082458   10533 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
E0720 00:01:32.120842   10533 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:37533/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1241&timeout=10s&timeoutSeconds=504&watch=true: dial tcp 127.0.0.1:37533: connect: connection refused
E0720 00:01:32.120843   10533 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:37533/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1241&timeout=10s&timeoutSeconds=593&watch=true: dial tcp 127.0.0.1:37533: connect: connection refused
E0720 00:01:32.120873   10533 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:37533/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1241&timeout=10s&timeoutSeconds=569&watch=true: dial tcp 127.0.0.1:37533: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	60.195s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 260 lines ...
I0720 00:00:46.624406   10952 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=43047
I0720 00:00:46.624712   10952 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0720 00:00:46.655967   10952 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}}}
I0720 00:00:46.859444   10952 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0720 00:00:46.859514   10952 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0720 00:00:47.161802   10952 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0720 00:00:49.238233   10952 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-vqlkx/test-cluster"
•E0720 00:00:49.706275   10952 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-qf894/test-cluster"
•E0720 00:00:50.249756   10952 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:35587/?timeout=50ms: dial tcp 127.0.0.1:35587: connect: connection refused"  "cluster"="cluster-cache-test-8w5fw/test-cluster"
•I0720 00:00:50.485654   10952 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":{}}}
I0720 00:00:50.686119   10952 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0720 00:00:50.686187   10952 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0720 00:00:50.686259   10952 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•E0720 00:00:51.217586   10952 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0720 00:00:51.217673   10952 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-005756637/tls.crt: no such file or directory"  
I0720 00:00:51.217714   10952 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0720 00:00:51.217810   10952 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0720 00:00:51.272860   10952 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:33627/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:33627: connect: connection refused


Ran 5 of 5 Specs in 17.789 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (17.79s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	17.944s
?   	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
I0720 00:00:57.350385   11563 controller.go:130]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0720 00:00:57.351602   11563 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
I0720 00:00:57.352246   11563 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0720 00:00:57.352401   11563 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 192 lines ...
    --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s)
=== RUN   TestPreflightChecks
=== RUN   TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass
=== RUN   TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue
I0720 00:01:16.679763   11563 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
I0720 00:01:16.679894   11563 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: 1626739243
Will run 1 of 1 specs

E0720 00:01:16.717195   11563 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-eaf81c\" not found" "kubeadmControlPlane"="kcp-foo-eaf81c" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.034 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0720 00:01:16.718668   11563 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-7f2wvz" "kubeadmControlPlane"="kcp-foo-7f2wvz" "namespace"="test" 
I0720 00:01:18.775521   11563 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-7f2wvz" "kubeadmControlPlane"="kcp-foo-7f2wvz" "namespace"="test" "needRollout"=["kcp-foo-7f2wvz-s8z28"]
I0720 00:01:18.775682   11563 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-7f2wvz" "kubeadmControlPlane"="kcp-foo-7f2wvz" "namespace"="test" "failures"="[machine kcp-foo-7f2wvz-zs2mb does not have APIServerPodHealthy condition, machine kcp-foo-7f2wvz-zs2mb does not have ControllerManagerPodHealthy condition, machine kcp-foo-7f2wvz-zs2mb does not have SchedulerPodHealthy condition, machine kcp-foo-7f2wvz-zs2mb does not have EtcdPodHealthy condition, machine kcp-foo-7f2wvz-zs2mb does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.06s)
... skipping 60 lines ...
==================================
Random Seed: 1626739243
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: 1626739243
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 297 lines ...
    --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s)
    --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s)
=== RUN   TestRemoveMachineFromKubeadmConfigMap
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0
E0720 00:00:58.496061   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:01:06.819741   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:01:15.805756   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:01:26.935981   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:01:43.409300   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:01:56.418025   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:02:14.065544   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:02:34.988974   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:03:06.005592   11514 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0720 00:03:51.162820   11514 workload_cluster.go:325]  "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 72 lines ...
=== RUN   TestClusterStatus/returns_cluster_status_with_kubeadm_config
--- PASS: TestClusterStatus (0.00s)
    --- PASS: TestClusterStatus/returns_cluster_status (0.00s)
    --- PASS: TestClusterStatus/returns_cluster_status_with_kubeadm_config (0.00s)
PASS
I0720 00:03:51.171404   11514 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0720 00:03:51.171565   11514 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0720 00:03:51.171621   11514 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-796947026/tls.crt: no such file or directory"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	188.263s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
... skipping 287 lines ...
I0720 00:01:06.266224   11810 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0720 00:01:06.266494   11810 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0720 00:01:06.366921   11810 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0720 00:01:06.467327   11810 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0720 00:01:06.467395   11810 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0720 00:01:06.547483   11810 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-67x14q"} 
•E0720 00:01:06.585466   11810 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"
I0720 00:01:07.640484   11810 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-mwogy8"} 
•E0720 00:01:07.707782   11810 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"
E0720 00:01:18.797359   11810 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"

------------------------------
• Failure [11.106 seconds]
ClusterResourceSet Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:40
  Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources [It]
... skipping 8 lines ...
------------------------------
STEP: Creating the Cluster
STEP: Creating the remote Cluster kubeconfig
STEP: Creating a Secret and a ConfigMap with ConfigMap in their data field
STEP: Verifying ClusterResourceSetBinding is created with cluster owner reference
STEP: Deleting the Kubeconfigsecret
E0720 00:01:19.948667   11810 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"
E0720 00:01:20.970546   11810 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"
•E0720 00:01:21.984242   11810 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"
•I0720 00:01:21.992383   11810 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0720 00:01:21.992448   11810 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0720 00:01:21.992516   11810 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  



Summarizing 1 Failure:

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

Ran 5 of 5 Specs in 29.919 seconds
FAIL! -- 4 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestAPIs (29.92s)
FAIL
FAIL	sigs.k8s.io/cluster-api/exp/addons/controllers	30.014s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-create
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-update
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-delete
... skipping 58 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0720 00:00:58.178135   12025 machinepool_controller_phases.go:237]  "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
=== RUN   TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused
--- PASS: TestReconcileMachinePoolInfrastructure (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestMachinePoolFinalizer
... skipping 92 lines ...
•I0720 00:01:09.991027   12025 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0720 00:01:10.020543   12025 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0720 00:01:10.022657   12025 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0720 00:01:10.032523   12025 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}}}
I0720 00:01:10.043436   12025 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0720 00:01:10.087879   12025 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0720 00:01:10.090321   12025 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0720 00:01:10.090385   12025 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-253333462/tls.crt: no such file or directory"  
E0720 00:01:10.090406   12025 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0720 00:01:10.090424   12025 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-253333462/tls.crt: no such file or directory"  
I0720 00:01:10.090530   12025 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 11.868 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (11.87s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	12.188s
?   	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 200 lines ...
I0720 00:01:38.788199   15088 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0720 00:01:38.788224   15088 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0720 00:01:38.788779   15088 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0720 00:01:38.790420   15088 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0720 00:01:38.790708   15088 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=46281
I0720 00:01:38.790761   15088 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••E0720 00:01:39.909181   15088 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0720 00:01:39.909223   15088 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-821375680/tls.crt: no such file or directory"  
E0720 00:01:39.909250   15088 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0720 00:01:39.909268   15088 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-821375680/tls.crt: no such file or directory"  
I0720 00:01:39.909291   15088 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


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