This job view page is being replaced by Spyglass soon. Check out the new job view.
PRykakarap: 🐛 clusterctl: use newest release series of same contract
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-12 18:48
Elapsed4m21s
Revision96dc88abebaf763bb9b29002831c14878bb8ffa2
Refs 4923

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0712 18:49:46.436341    8562 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0712 18:49:46.436535    8562 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0712 18:49:46.437390    8562 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0712 18:49:46.437600    8562 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=40477
I0712 18:49:46.437781    8562 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0712 18:49:46.974281    8562 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" 
•E0712 18:49:46.984234    8562 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 18:49:46.984307    8562 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-882964756/tls.crt: no such file or directory"  
I0712 18:49:46.984343    8562 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 11.520 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (11.52s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	39.233s
=== 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 1400 lines ...
I0712 18:49:33.385089   10456 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinehealthcheck" 
I0712 18:49:33.385124   10456 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0712 18:49:33.386692   10456 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0712 18:49:33.388553   10456 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
2021/07/12 18:49:33 http: TLS handshake error from 127.0.0.1:41318: EOF
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0712 18:49:33.584201   10456 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"
I0712 18:49:33.596755   10456 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infra_config_is_marked_for_deletion
I0712 18:49:33.597973   10456 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"
... skipping 103 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0712 18:49:33.624331   10456 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
I0712 18:49:33.625828   10456 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"
E0712 18:49:33.626167   10456 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
I0712 18:49:33.626611   10456 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
I0712 18:49:33.872171   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0712 18:49:33.972963   10456 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0712 18:49:33.980510   10456 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0712 18:49:33.980617   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0712 18:49:34.088959   10456 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0712 18:49:34.089056   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0712 18:49:34.189498   10456 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv" "noderef"="node-1"
E0712 18:49:34.196490   10456 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0712 18:49:34.196536   10456 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0712 18:49:34.270197   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-mxmnz\" in namespace \"test-machine-watches-mp7rv\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv"
E0712 18:49:35.275340   10456 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-mxmnz\" in namespace \"test-machine-watches-mp7rv\", requeuing: requeue in 1s"  
E0712 18:49:35.282504   10456 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-mxmnz\" in namespace \"test-machine-watches-mp7rv\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-mxmnz\" in namespace \"test-machine-watches-mp7rv\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv"
--- PASS: TestWatches (1.69s)
=== 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
I0712 18:49:35.504831   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-4v942" "namespace"="test-machine-watches-mp7rv" "count"=1
I0712 18:49:35.504908   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-4v942" "namespace"="test-machine-watches-mp7rv" "descendants"="Worker machines: machine-created-mxmnz" "indirect descendants count"=0
I0712 18:49:35.523119   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-4v942" "namespace"="test-machine-watches-mp7rv" "count"=1
I0712 18:49:35.523183   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-4v942" "namespace"="test-machine-watches-mp7rv" "descendants"="Worker machines: machine-created-mxmnz" "indirect descendants count"=0
I0712 18:49:36.283045   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-4v942" "machine"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"6b5782cb-6feb-4e7e-acea-cc2b6f4d8c6e","apiVersion":"v1"}
E0712 18:49:36.348311   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-mxmnz\" not found" "controller"="machine" "name"="machine-created-mxmnz" "namespace"="test-machine-watches-mp7rv"
E0712 18:49:37.408519   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-jqlxx\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-4rfxs\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-4rfxs: secrets \"machine-reconcile-4rfxs-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-jqlxx" "namespace"="default"
I0712 18:49:38.409096   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-4rfxs" "machine"="machine-created-jqlxx" "namespace"="default" "cause"="noderef is nil" "node"=null
I0712 18:49:38.475659   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-4rfxs" "machine"="machine-created-jqlxx" "namespace"="default" "cause"="noderef is nil" "node"=null
I0712 18:49:38.509389   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-4rfxs" "machine"="machine-created-jqlxx" "namespace"="default" "cause"="noderef is nil" "node"=null
E0712 18:49:38.541966   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-jqlxx\" not found" "controller"="machine" "name"="machine-created-jqlxx" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.24s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.24s)
=== RUN   TestMachineFinalizer
=== RUN   TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one
=== RUN   TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer
--- PASS: TestMachineFinalizer (0.00s)
... skipping 3 lines ...
=== RUN   TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta
I0712 18:49:38.552665   10456 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"
I0712 18:49:38.552779   10456 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
I0712 18:49:38.560926   10456 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"
I0712 18:49:38.561065   10456 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine3" "namespace"="default" 
E0712 18:49:38.561084   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-4rfxs\" not found" "controller"="cluster" "name"="machine-reconcile-4rfxs" "namespace"="default"
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner
I0712 18:49:38.563583   10456 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"
I0712 18:49:38.563647   10456 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
--- PASS: TestMachineOwnerReference (0.01s)
    --- 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 120 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s)
    --- PASS: TestMachineDeploymentSyncStatus/all_machines_are_running (0.00s)
    --- PASS: TestMachineDeploymentSyncStatus/scaling_up (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0712 18:49:38.816500   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hgvfh" "namespace"="test-mhc-zm28p" 
E0712 18:49:38.850850   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-56pk2\" not found"  "cluster"="test-mhc-zm28p/test-cluster-56pk2"
I0712 18:49:38.850922   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist
E0712 18:49:38.956428   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-hgvfh\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-hgvfh\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-hgvfh" "namespace"="test-mhc-zm28p"
error cannot retrieve mhc in ctx: MachineHealthCheck.cluster.x-k8s.io "test-mhc-flc6l" not foundI0712 18:49:39.956809   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zhvnd" "namespace"="test-mhc-z7wtl" 
I0712 18:49:39.956944   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z925b" "namespace"="test-mhc-jthkq" 
I0712 18:49:39.956995   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hgvfh" "namespace"="test-mhc-zm28p" 
I0712 18:49:39.957041   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flc6l" "namespace"="test-mhc-nqhlc" 
I0712 18:49:39.971584   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:49:39.988609   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flc6l" "namespace"="test-mhc-nqhlc" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I0712 18:49:40.081529   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flc6l" "namespace"="test-mhc-nqhlc" 
E0712 18:49:40.096971   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-nqhlc/test-cluster-qjdj5"
E0712 18:49:40.100956   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-qjdj5\" not found" "controller"="cluster" "name"="test-cluster-qjdj5" "namespace"="test-mhc-nqhlc"
I0712 18:49:40.111774   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-frqxf" "namespace"="test-mhc-6bcj7" 
I0712 18:49:40.135026   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:49:40.260447   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-frqxf" "namespace"="test-mhc-6bcj7" 
I0712 18:49:40.265114   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-frqxf" "namespace"="test-mhc-6bcj7" 
E0712 18:49:40.392566   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-6bcj7/test-cluster-s4ghc"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0712 18:49:40.397830   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-frqxf" "namespace"="test-mhc-6bcj7" 
I0712 18:49:40.527880   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
inframachine created: test-mhc-machine-infra-vjltr
machine created: test-mhc-machine-5zrqg
I0712 18:49:40.546376   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:49:40.583113   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
I0712 18:49:40.583434   10456 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-hvnv4/test-mhc-vhhc4/test-mhc-machine-5zrqg/"
E0712 18:49:40.645969   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fjj4m, got []"  "node"="test-mhc-node-fjj4m"
E0712 18:49:40.646189   10456 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-fjj4m"
node created: test-mhc-node-fjj4m
inframachine created: test-mhc-machine-infra-4tckh
I0712 18:49:40.661159   10456 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4" "noderef"="test-mhc-node-fjj4m"
machine created: test-mhc-machine-zms4k
E0712 18:49:40.779347   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jkf2r, got []"  "node"="test-mhc-node-jkf2r"
E0712 18:49:40.779594   10456 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-jkf2r"
node created: test-mhc-node-jkf2r
I0712 18:49:40.781982   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
I0712 18:49:40.782399   10456 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-hvnv4/test-mhc-vhhc4/test-mhc-machine-zms4k/"
I0712 18:49:40.945064   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
I0712 18:49:40.975899   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
I0712 18:49:40.983944   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
Cleaning up nodes, machines and infra machines.
I0712 18:49:40.995845   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
I0712 18:49:40.996301   10456 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hvnv4/test-mhc-vhhc4/test-mhc-machine-5zrqg/"
E0712 18:49:41.026829   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-hvnv4/test-cluster-bplz7"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
inframachine created: test-mhc-machine-infra-56nfg
machine created: test-mhc-machine-v4ngm
E0712 18:49:41.118693   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-mp7rv/machine-reconcile-4v942"
E0712 18:49:41.192776   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
E0712 18:49:41.214903   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-vhhc4\" not found" "controller"="machinehealthcheck" "name"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4"
E0712 18:49:42.193210   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:42.215244   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:42.231725   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:49:42.250843   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhhc4" "namespace"="test-mhc-hvnv4" 
I0712 18:49:42.250916   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:42.254778   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:42.255949   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 471 lines ...
I0712 18:49:43.202533   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.206031   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.206554   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.208073   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.209654   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.211420   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.211633   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-v4ngm/"
E0712 18:49:43.212647   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:49:43.228290   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.228624   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-v4ngm/"
node created: test-mhc-node-4r62p
E0712 18:49:43.297357   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4r62p, got []"  "node"="test-mhc-node-4r62p"
I0712 18:49:43.304146   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
inframachine created: test-mhc-machine-infra-8nkk2
I0712 18:49:43.320386   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:43.321463   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
machine created: test-mhc-machine-g7jdg
I0712 18:49:43.327518   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 347 lines ...
I0712 18:49:44.201869   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.203801   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.205697   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.207640   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.209556   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.211628   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
E0712 18:49:44.212996   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:44.213531   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.215710   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.217699   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.219672   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.221629   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:44.223609   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 420 lines ...
I0712 18:49:45.250377   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.252441   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.255162   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.257261   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.258720   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.267773   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
E0712 18:49:45.268407   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:49:45.269490   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.271221   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.272436   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.293724   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.298410   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:45.299759   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 380 lines ...
I0712 18:49:46.273254   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.275275   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.276985   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.277943   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.279854   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.284902   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.285332   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-g7jdg/"
E0712 18:49:46.286075   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:46.299520   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.299945   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-g7jdg/"
node created: test-mhc-node-2r9t7
E0712 18:49:46.348196   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2r9t7, got []"  "node"="test-mhc-node-2r9t7"
I0712 18:49:46.358338   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
inframachine created: test-mhc-machine-infra-x4rxn
I0712 18:49:46.374700   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
machine created: test-mhc-machine-k9vbz
I0712 18:49:46.381191   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:46.382589   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 247 lines ...
I0712 18:49:47.288720   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.291422   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.293903   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.297015   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.300439   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.312195   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
E0712 18:49:47.312322   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:49:47.314605   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.315682   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.317771   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.320018   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.322662   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:47.325450   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 287 lines ...
I0712 18:49:48.319809   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.322198   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.328219   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.330467   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.345956   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.348014   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
E0712 18:49:48.348601   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:48.350961   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.353172   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.354975   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.356521   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.358371   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:48.360006   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
... skipping 301 lines ...
I0712 18:49:49.355302   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.357480   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.358992   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.360315   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.361604   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.363184   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.363638   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-k9vbz/"
E0712 18:49:49.371964   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:49:49.379609   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.380246   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-k9vbz/"
E0712 18:49:49.401265   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6tbst, got []"  "node"="test-mhc-node-6tbst"
node created: test-mhc-node-6tbst
Cleaning up nodes, machines and infra machines.
I0712 18:49:49.413846   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.414305   10456 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-82mt6/test-mhc-4phrg/test-mhc-machine-k9vbz/test-mhc-node-6tbst"
I0712 18:49:49.425139   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4phrg" "namespace"="test-mhc-82mt6" 
I0712 18:49:49.425708   10456 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-82mt6/test-mhc-4phrg/test-mhc-machine-k9vbz/"
Cleaning up nodes, machines and infra machines.
I0712 18:49:49.478074   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-q6w8f" "namespace"="test-mhc-82mt6" "count"=2
I0712 18:49:49.478143   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-q6w8f" "namespace"="test-mhc-82mt6" "descendants"="Worker machines: test-mhc-machine-v4ngm,test-mhc-machine-g7jdg,test-mhc-machine-k9vbz" "indirect descendants count"=1
I0712 18:49:49.482958   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-q6w8f" "namespace"="test-mhc-82mt6" "count"=2
I0712 18:49:49.483011   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-q6w8f" "namespace"="test-mhc-82mt6" "descendants"="Worker machines: test-mhc-machine-v4ngm,test-mhc-machine-g7jdg,test-mhc-machine-k9vbz" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
... skipping 7 lines ...
I0712 18:49:49.764931   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:49.806309   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:49.887417   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:50.054048   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:50.372554   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-q6w8f" "machine"="test-mhc-machine-g7jdg" "namespace"="test-mhc-82mt6" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-2r9t7"}
I0712 18:49:50.375047   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:50.422427   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-g7jdg\" not found" "controller"="machine" "name"="test-mhc-machine-g7jdg" "namespace"="test-mhc-82mt6"
I0712 18:49:51.016695   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:51.422905   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:52.297716   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:52.423380   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-q6w8f" "machine"="test-mhc-machine-k9vbz" "namespace"="test-mhc-82mt6" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6tbst"}
E0712 18:49:52.461977   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-k9vbz\" not found" "controller"="machine" "name"="test-mhc-machine-k9vbz" "namespace"="test-mhc-82mt6"
E0712 18:49:53.462519   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:49:54.463127   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-q6w8f" "machine"="test-mhc-machine-v4ngm" "namespace"="test-mhc-82mt6" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-4r62p"}
I0712 18:49:54.482356   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-q6w8f" "namespace"="test-mhc-82mt6" "count"=1
I0712 18:49:54.482456   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-q6w8f" "namespace"="test-mhc-82mt6" "descendants"="Worker machines: test-mhc-machine-v4ngm" "indirect descendants count"=0
E0712 18:49:54.500032   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-v4ngm\" not found" "controller"="machine" "name"="test-mhc-machine-v4ngm" "namespace"="test-mhc-82mt6"
I0712 18:49:54.858710   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.508644   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:55.514671   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:55.514959   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.538026   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:55.578984   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-v56cm, got []"  "node"="test-mhc-node-v56cm"
node created: test-mhc-node-v56cm
E0712 18:49:55.579268   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-v56cm, got []"  "node"="test-mhc-node-v56cm"
I0712 18:49:55.587013   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
inframachine created: test-mhc-machine-infra-6ctmq
machine created: test-mhc-machine-l6vgn
I0712 18:49:55.611634   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.787538   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.788409   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.793486   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.834647   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:55.916029   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:56.077940   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:56.400492   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:56.515089   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:49:57.041741   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.534001   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.535259   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.541033   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.548892   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.554278   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.563175   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.568803   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:57.568944   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:57.597857   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:57.618195   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wks7c, got []"  "node"="test-mhc-node-wks7c"
node created: test-mhc-node-wks7c
E0712 18:49:57.618555   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wks7c, got []"  "node"="test-mhc-node-wks7c"
I0712 18:49:57.626076   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
inframachine created: test-mhc-machine-infra-jbb76
I0712 18:49:57.639373   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.647183   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
machine created: test-mhc-machine-bg7fz
I0712 18:49:57.659730   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:57.665155   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:58.323021   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:58.569438   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
E0712 18:49:59.505977   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-82mt6/test-cluster-q6w8f"
I0712 18:49:59.583232   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.599203   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.608375   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.626141   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.632296   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.641592   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
E0712 18:49:59.647605   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:49:59.647694   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
node created: test-mhc-node-d52sh
E0712 18:49:59.667230   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d52sh, got []"  "node"="test-mhc-node-d52sh"
I0712 18:49:59.671511   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
Cleaning up nodes, machines and infra machines.
I0712 18:49:59.673003   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.689775   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
Cleaning up nodes, machines and infra machines.
I0712 18:49:59.732270   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-4wbpd" "namespace"="test-mhc-gfgzn" "count"=2
... skipping 4 lines ...
inframachine created: test-mhc-machine-infra-mkzfb
machine created: test-mhc-machine-9cfd8
I0712 18:49:59.889058   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:49:59.905087   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:49:59.928413   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xhmrf" "namespace"="test-mhc-gfgzn" 
I0712 18:49:59.928496   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
E0712 18:50:00.648036   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:50:01.648667   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-4wbpd" "machine"="test-mhc-machine-p26jf" "namespace"="test-mhc-gfgzn" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-v56cm"}
E0712 18:50:01.747574   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-p26jf\" not found" "controller"="machine" "name"="test-mhc-machine-p26jf" "namespace"="test-mhc-gfgzn"
I0712 18:50:02.748114   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-4wbpd" "machine"="test-mhc-machine-l6vgn" "namespace"="test-mhc-gfgzn" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-wks7c"}
E0712 18:50:02.787704   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-l6vgn\" not found" "controller"="machine" "name"="test-mhc-machine-l6vgn" "namespace"="test-mhc-gfgzn"
I0712 18:50:03.788200   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-4wbpd" "machine"="test-mhc-machine-bg7fz" "namespace"="test-mhc-gfgzn" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-d52sh"}
E0712 18:50:03.896667   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-bg7fz\" not found" "controller"="machine" "name"="test-mhc-machine-bg7fz" "namespace"="test-mhc-gfgzn"
E0712 18:50:04.753446   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-gfgzn/test-cluster-4wbpd"
I0712 18:50:04.905570   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:04.911527   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
E0712 18:50:04.912669   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
node created: test-mhc-node-6hzn6
E0712 18:50:05.013058   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6hzn6, got []"  "node"="test-mhc-node-6hzn6"
I0712 18:50:05.019112   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
inframachine created: test-mhc-machine-infra-69zb5
machine created: test-mhc-machine-2pn58
I0712 18:50:05.036279   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:05.046030   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
E0712 18:50:05.913170   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:50:06.938671   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:06.941258   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:06.949176   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:06.954349   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:06.961383   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
E0712 18:50:06.965915   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:50:06.966218   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
node created: test-mhc-node-d7qn2
E0712 18:50:07.050894   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d7qn2, got []"  "node"="test-mhc-node-d7qn2"
I0712 18:50:07.058114   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
inframachine created: test-mhc-machine-infra-2sx8f
machine created: test-mhc-machine-49t2g
I0712 18:50:07.078272   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:07.086985   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:07.975792   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
... skipping 6 lines ...
Cleaning up nodes, machines and infra machines.
I0712 18:50:08.178486   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:08.183275   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
Cleaning up nodes, machines and infra machines.
I0712 18:50:08.201269   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:08.202891   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:08.203351   10456 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-79kvk/test-mhc-wxjx9/test-mhc-machine-9cfd8/"
I0712 18:50:08.240137   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:08.240934   10456 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-79kvk/test-mhc-wxjx9/test-mhc-machine-9cfd8/"
I0712 18:50:08.241395   10456 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-79kvk/test-mhc-wxjx9/test-mhc-machine-2pn58/"
E0712 18:50:08.260094   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-2pn58\" in namespace \"test-mhc-79kvk\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-2pn58" "namespace"="test-mhc-79kvk"
I0712 18:50:08.260454   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-2z4g2" "namespace"="test-mhc-79kvk" "count"=3
I0712 18:50:08.260518   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2z4g2" "namespace"="test-mhc-79kvk" "descendants"="Worker machines: test-mhc-machine-9cfd8,test-mhc-machine-2pn58,test-mhc-machine-49t2g" "indirect descendants count"=0
I0712 18:50:08.266258   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-2z4g2" "namespace"="test-mhc-79kvk" "count"=3
I0712 18:50:08.266329   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2z4g2" "namespace"="test-mhc-79kvk" "descendants"="Worker machines: test-mhc-machine-9cfd8,test-mhc-machine-2pn58,test-mhc-machine-49t2g" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_longer_than_the_NodeStartupTimeout
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine's_Node_has_gone_away
=== RUN   TestMachineHealthCheck_Reconcile/should_react_when_a_Node_transitions_to_unhealthy
inframachine created: test-mhc-machine-infra-969hm
E0712 18:50:08.427106   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-wxjx9\" not found" "controller"="machinehealthcheck" "name"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk"
machine created: test-mhc-machine-qvnxj
I0712 18:50:09.260774   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-2z4g2" "machine"="test-mhc-machine-9cfd8" "namespace"="test-mhc-79kvk" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6hzn6"}
E0712 18:50:09.320517   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9cfd8\" not found" "controller"="machine" "name"="test-mhc-machine-9cfd8" "namespace"="test-mhc-79kvk"
I0712 18:50:09.427437   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:09.443808   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:50:09.462848   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wxjx9" "namespace"="test-mhc-79kvk" 
I0712 18:50:09.462926   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:09.463896   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:09.465544   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
... skipping 444 lines ...
I0712 18:50:10.349319   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.351041   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.352975   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.354807   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.356766   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.358507   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
E0712 18:50:10.359237   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-49t2g\" not found" "controller"="machine" "name"="test-mhc-machine-49t2g" "namespace"="test-mhc-79kvk"
I0712 18:50:10.360494   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.362361   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.364444   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.366399   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.368305   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:10.370094   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
... skipping 533 lines ...
I0712 18:50:11.389296   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.391293   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.393383   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.395315   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.397221   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.399301   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
E0712 18:50:11.401451   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2pn58\" not found" "controller"="machine" "name"="test-mhc-machine-2pn58" "namespace"="test-mhc-79kvk"
I0712 18:50:11.401486   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.403311   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.404906   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.406712   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.408401   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:11.410240   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
... skipping 532 lines ...
I0712 18:50:12.407848   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.409572   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.410640   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.411205   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.412714   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.414392   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
E0712 18:50:12.414692   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:50:12.414917   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.415068   10456 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-dlzt9/test-mhc-nnxf7/test-mhc-machine-qvnxj/"
I0712 18:50:12.430247   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.430483   10456 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-dlzt9/test-mhc-nnxf7/test-mhc-machine-qvnxj/"
E0712 18:50:12.443631   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ctln7, got []"  "node"="test-mhc-node-ctln7"
node created: test-mhc-node-ctln7
E0712 18:50:12.444150   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ctln7, got []"  "node"="test-mhc-node-ctln7"
I0712 18:50:12.450711   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.467414   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.472187   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.475471   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.475839   10456 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-dlzt9/test-mhc-nnxf7/test-mhc-machine-qvnxj/test-mhc-node-ctln7"
I0712 18:50:12.490652   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.490994   10456 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-dlzt9/test-mhc-nnxf7/test-mhc-machine-qvnxj/test-mhc-node-ctln7"
Cleaning up nodes, machines and infra machines.
I0712 18:50:12.501260   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.501733   10456 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-dlzt9/test-mhc-nnxf7/test-mhc-machine-qvnxj/"
I0712 18:50:12.514494   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zgllf" "namespace"="test-mhc-dlzt9" "descendants"="Worker machines: test-mhc-machine-qvnxj" "indirect descendants count"=1
I0712 18:50:12.518315   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zgllf" "namespace"="test-mhc-dlzt9" "descendants"="Worker machines: test-mhc-machine-qvnxj" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0712 18:50:12.590961   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" "creating"=1 "need"=1
I0712 18:50:12.591005   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" 
I0712 18:50:12.601976   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-nvj57-zvh7d\"" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" 
I0712 18:50:12.674184   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnxf7" "namespace"="test-mhc-dlzt9" 
I0712 18:50:12.681112   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:12.695104   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 18:50:12.812510   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:12.813183   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
E0712 18:50:13.278822   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-79kvk/test-cluster-2z4g2"
E0712 18:50:13.415312   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:50:13.812793   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:14.415959   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-zgllf" "machine"="test-mhc-machine-qvnxj" "namespace"="test-mhc-dlzt9" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-ctln7"}
E0712 18:50:14.453893   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-qvnxj\" not found" "controller"="machine" "name"="test-mhc-machine-qvnxj" "namespace"="test-mhc-dlzt9"
I0712 18:50:14.813856   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.462548   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.463244   10456 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.468985   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.469113   10456 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.478910   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
... skipping 7 lines ...
I0712 18:50:15.512591   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.512641   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:15.814902   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:16.494443   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:16.494491   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.000634   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.001148   10456 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-gkcfz/test-mhc-l2vrb/mhc-ms-nvj57-zvh7d/"
I0712 18:50:17.007881   10456 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.011613   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.011685   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.012044   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.012277   10456 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-gkcfz/test-mhc-l2vrb/mhc-ms-nvj57-zvh7d/"
I0712 18:50:17.017303   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-l2vrb" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.017717   10456 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-gkcfz/test-mhc-l2vrb/mhc-ms-nvj57-zvh7d/"
I0712 18:50:17.017717   10456 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.027891   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.027930   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" 
I0712 18:50:17.117448   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-s489p" "namespace"="test-mhc-gkcfz" "count"=1
I0712 18:50:17.117518   10456 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-s489p" "namespace"="test-mhc-gkcfz" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-nvj57"
I0712 18:50:17.117789   10456 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-nvj57" "namespace"="test-mhc-gkcfz" "machine"="mhc-ms-nvj57-zvh7d"
... skipping 5 lines ...
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created
I0712 18:50:17.284717   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
inframachine created: test-mhc-machine-infra-7ggrw
I0712 18:50:17.300628   10456 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-xxjh2
I0712 18:50:17.360493   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-s489p" "machine"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz" "cause"="cluster is being deleted" "node"=null
E0712 18:50:17.387068   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-nvj57-zvh7d\" not found" "controller"="machine" "name"="mhc-ms-nvj57-zvh7d" "namespace"="test-mhc-gkcfz"
node created: test-mhc-node-k4ngw
E0712 18:50:17.408115   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k4ngw, got []"  "node"="test-mhc-node-k4ngw"
E0712 18:50:17.408164   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k4ngw, got []"  "node"="test-mhc-node-k4ngw"
E0712 18:50:17.408164   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k4ngw, got []"  "node"="test-mhc-node-k4ngw"
I0712 18:50:17.427059   10456 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-xxjh2" "target"="test-mhc-jqc9c/test-mhc-86w8m/test-mhc-machine-xxjh2/"
I0712 18:50:17.458640   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
I0712 18:50:17.478463   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
I0712 18:50:17.486381   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
I0712 18:50:17.489389   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
I0712 18:50:17.493785   10456 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-xxjh2" "target"="test-mhc-jqc9c/test-mhc-86w8m/test-mhc-machine-xxjh2/test-mhc-node-k4ngw"
I0712 18:50:17.511391   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
Cleaning up nodes, machines and infra machines.
I0712 18:50:17.527398   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
E0712 18:50:17.529864   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-dlzt9/test-cluster-zgllf"
I0712 18:50:17.531215   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
I0712 18:50:17.538066   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-scd2r" "namespace"="test-mhc-jqc9c" "descendants"="Worker machines: test-mhc-machine-xxjh2" "indirect descendants count"=1
I0712 18:50:17.547045   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-86w8m" "namespace"="test-mhc-jqc9c" 
I0712 18:50:17.547683   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-scd2r" "namespace"="test-mhc-jqc9c" "descendants"="Worker machines: test-mhc-machine-xxjh2" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted
I0712 18:50:17.574300   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
... skipping 372 lines ...
I0712 18:50:18.415522   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.417341   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.419429   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.421384   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.423313   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.425213   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
E0712 18:50:18.425642   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-xxjh2\" not found" "controller"="machine" "name"="test-mhc-machine-xxjh2" "namespace"="test-mhc-jqc9c"
I0712 18:50:18.427069   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.428821   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.430666   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.432658   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.434398   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:18.436390   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
... skipping 521 lines ...
I0712 18:50:19.417090   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.418809   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.420704   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.422224   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.423810   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.425610   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
E0712 18:50:19.425974   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
I0712 18:50:19.427347   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.428957   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.430745   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.432527   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.434083   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:19.435819   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
... skipping 529 lines ...
I0712 18:50:20.434001   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.435757   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.436534   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.438059   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.439048   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.441809   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
E0712 18:50:20.442118   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
I0712 18:50:20.446838   10456 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-4frtc" "target"="test-mhc-k2ldr/test-mhc-rnfr8/test-mhc-machine-4frtc/"
I0712 18:50:20.457808   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
node created: test-mhc-node-lhqjp
E0712 18:50:20.502241   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-lhqjp, got []"  "node"="test-mhc-node-lhqjp"
E0712 18:50:20.502335   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-lhqjp, got []"  "node"="test-mhc-node-lhqjp"
E0712 18:50:20.502556   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-lhqjp, got []"  "node"="test-mhc-node-lhqjp"
I0712 18:50:20.509712   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.529441   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.532535   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.534796   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.538140   10456 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-4frtc" "target"="test-mhc-k2ldr/test-mhc-rnfr8/test-mhc-machine-4frtc/test-mhc-node-lhqjp"
I0712 18:50:20.554037   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.557444   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.577365   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
Cleaning up nodes, machines and infra machines.
I0712 18:50:20.586909   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.589253   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:20.594002   10456 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-4frtc" "target"="test-mhc-k2ldr/test-mhc-rnfr8/test-mhc-machine-4frtc/"
I0712 18:50:20.602529   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r8bpl" "namespace"="test-mhc-k2ldr" "descendants"="Worker machines: test-mhc-machine-4frtc" "indirect descendants count"=1
I0712 18:50:20.607099   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r8bpl" "namespace"="test-mhc-k2ldr" "descendants"="Worker machines: test-mhc-machine-4frtc" "indirect descendants count"=1
E0712 18:50:20.612359   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-rnfr8\" not found" "controller"="machinehealthcheck" "name"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr"
--- PASS: TestMachineHealthCheck_Reconcile (41.92s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.16s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.03s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.04s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (1.16s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.32s)
... skipping 10 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (0.42s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (3.06s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0712 18:50:20.615343   10456 machinehealthcheck_controller.go:416]  "msg"="expected a Cluster" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Cluster_in_the_same_namespace
=== RUN   TestClusterToMachineHealthCheck/when_2_MachineHealthChecks_exists_for_the_Cluster_in_the_same_namespace
=== RUN   TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_the_same_namespace
=== RUN   TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_another_namespace
--- PASS: TestClusterToMachineHealthCheck (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Cluster_in_the_same_namespace (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_2_MachineHealthChecks_exists_for_the_Cluster_in_the_same_namespace (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_the_same_namespace (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_another_namespace (0.00s)
=== RUN   TestMachineToMachineHealthCheck
=== RUN   TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine
E0712 18:50:20.616637   10456 machinehealthcheck_controller.go:445]  "msg"="expected a Machine" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace
--- PASS: TestMachineToMachineHealthCheck (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace (0.00s)
=== RUN   TestNodeToMachineHealthCheck
=== RUN   TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node
E0712 18:50:20.617879   10456 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0712 18:50:20.618061   10456 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
E0712 18:50:20.618472   10456 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
I0712 18:50:20.621225   10456 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0712 18:50:20.621645   10456 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0712 18:50:20.622916   10456 machinehealthcheck_controller.go:320]  "msg"="failed to patch healthy machine status for machine" "error"="machines.cluster.x-k8s.io \"machine1\" not found"  "machine"="machine1"
--- PASS: TestPatchTargets (0.00s)
=== RUN   TestGetTargetsFromMHC
=== RUN   TestGetTargetsFromMHC/with_no_matching_machines
=== RUN   TestGetTargetsFromMHC/when_a_machine's_node_is_missing
=== RUN   TestGetTargetsFromMHC/when_a_machine's_labels_do_not_match_the_selector
=== RUN   TestGetTargetsFromMHC/with_multiple_machines,_should_match_correct_nodes
... skipping 26 lines ...
--- PASS: TestMachineSetOwnerReference (0.00s)
    --- PASS: TestMachineSetOwnerReference/should_add_cluster_owner_reference_to_machine_set (0.00s)
    --- PASS: TestMachineSetOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_deployment (0.00s)
=== RUN   TestMachineSetReconcile
=== RUN   TestMachineSetReconcile/ignore_machine_sets_marked_for_deletion
=== RUN   TestMachineSetReconcile/records_event_if_reconcile_fails
E0712 18:50:20.631296   10456 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
E0712 18:50:20.632885   10456 machineset_controller.go:569]  "msg"="Unable to convert selector" "error"="\"bad-operator\" is not a valid pod selector operator" "machine"="match" "machineset"="" "namespace"="" 
--- PASS: TestHasMatchingLabels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_empty_selector (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_bad_selector (0.00s)
=== RUN   TestMachineToDelete
... skipping 82 lines ...
I0712 18:50:20.648641   10456 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"
•I0712 18:50:20.650026   10456 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"
I0712 18:50:20.650661   10456 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"
I0712 18:50:20.651220   10456 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0712 18:50:20.651248   10456 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0712 18:50:20.651661   10456 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0712 18:50:20.653080   10456 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" 
•I0712 18:50:20.719765   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0712 18:50:20.719823   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" 
I0712 18:50:20.731524   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-5zt2n-6657c7fddb-76zjz\"" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" 
I0712 18:50:20.731613   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" 
I0712 18:50:20.747700   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-5zt2n-6657c7fddb-56b6d\"" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" 
I0712 18:50:20.813889   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
... skipping 4 lines ...
I0712 18:50:20.925929   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0712 18:50:20.925989   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" 
I0712 18:50:20.937379   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-6657c7fddb-x6mtr\"" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" 
I0712 18:50:21.036896   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0712 18:50:21.036940   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
I0712 18:50:21.055132   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-cdfc6fd6c-4nxs2\"" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
E0712 18:50:21.137610   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.137641   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.137713   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.241697   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.241772   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.241817   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.241855   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.241952   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.241869   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg, got []"  "node"="md-5zt2n-cdfc6fd6c-4nxs2-hvmsg"
E0712 18:50:21.264547   10456 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-5zt2n-cdfc6fd6c-4nxs2-hvmsg for machine md-test/md-5zt2n-cdfc6fd6c-4nxs2: the cache is not started, can not read objects" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
I0712 18:50:21.296468   10456 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0712 18:50:21.296555   10456 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0712 18:50:21.303990   10456 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "machine"="md-5zt2n-6657c7fddb-z2kvg"
I0712 18:50:21.330396   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0712 18:50:21.330499   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
I0712 18:50:21.342085   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-cdfc6fd6c-gnn25\"" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
E0712 18:50:21.376635   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.376950   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.377101   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.379909   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.380086   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.379909   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.380118   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.379951   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
E0712 18:50:21.380148   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-gnn25-cb4sf, got []"  "node"="md-5zt2n-cdfc6fd6c-gnn25-cb4sf"
I0712 18:50:21.424314   10456 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0712 18:50:21.424354   10456 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0712 18:50:21.428625   10456 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "machine"="md-5zt2n-6657c7fddb-bt796"
I0712 18:50:21.442779   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-r8bpl" "machine"="test-mhc-machine-4frtc" "namespace"="test-mhc-k2ldr" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-lhqjp"}
E0712 18:50:21.480728   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-4frtc\" not found" "controller"="machine" "name"="test-mhc-machine-4frtc" "namespace"="test-mhc-k2ldr"
I0712 18:50:21.612749   10456 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rnfr8" "namespace"="test-mhc-k2ldr" 
I0712 18:50:21.621547   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0712 18:50:21.621606   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
I0712 18:50:21.635057   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-cdfc6fd6c-xl54v\"" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" 
E0712 18:50:21.761600   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.762014   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.762125   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.765426   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.765471   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.765505   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.765507   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.765783   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
E0712 18:50:21.765884   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-cdfc6fd6c-xl54v-slr27, got []"  "node"="md-5zt2n-cdfc6fd6c-xl54v-slr27"
I0712 18:50:21.801056   10456 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0712 18:50:21.801112   10456 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0712 18:50:21.805631   10456 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-5zt2n-6657c7fddb" "namespace"="md-test" "machine"="md-5zt2n-6657c7fddb-x6mtr"
I0712 18:50:22.065699   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0712 18:50:22.065820   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" 
I0712 18:50:22.079964   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-74d45c49c5-pvmtj\"" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" 
E0712 18:50:22.143919   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-gkcfz/test-cluster-s489p"
E0712 18:50:22.157567   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-pvmtj-rdr7l, got []"  "node"="md-5zt2n-74d45c49c5-pvmtj-rdr7l"
E0712 18:50:22.157914   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-pvmtj-rdr7l, got []"  "node"="md-5zt2n-74d45c49c5-pvmtj-rdr7l"
E0712 18:50:22.262055   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-pvmtj-rdr7l, got []"  "node"="md-5zt2n-74d45c49c5-pvmtj-rdr7l"
E0712 18:50:22.262118   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-pvmtj-rdr7l, got []"  "node"="md-5zt2n-74d45c49c5-pvmtj-rdr7l"
E0712 18:50:22.262207   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-pvmtj-rdr7l, got []"  "node"="md-5zt2n-74d45c49c5-pvmtj-rdr7l"
E0712 18:50:22.262335   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-pvmtj-rdr7l, got []"  "node"="md-5zt2n-74d45c49c5-pvmtj-rdr7l"
I0712 18:50:22.300189   10456 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0712 18:50:22.300242   10456 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0712 18:50:22.304711   10456 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "machine"="md-5zt2n-cdfc6fd6c-xl54v"
I0712 18:50:22.414575   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0712 18:50:22.414627   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" 
I0712 18:50:22.425207   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-74d45c49c5-frpbh\"" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" 
E0712 18:50:22.498323   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-frpbh-zt856, got []"  "node"="md-5zt2n-74d45c49c5-frpbh-zt856"
E0712 18:50:22.498661   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-frpbh-zt856, got []"  "node"="md-5zt2n-74d45c49c5-frpbh-zt856"
E0712 18:50:22.564719   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-jqc9c/test-cluster-scd2r"
I0712 18:50:22.566938   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:22.566982   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:22.584821   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:22.584871   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
E0712 18:50:22.601061   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-frpbh-zt856, got []"  "node"="md-5zt2n-74d45c49c5-frpbh-zt856"
E0712 18:50:22.601099   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-frpbh-zt856, got []"  "node"="md-5zt2n-74d45c49c5-frpbh-zt856"
E0712 18:50:22.626155   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
I0712 18:50:22.643760   10456 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0712 18:50:22.643798   10456 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0712 18:50:22.650001   10456 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-5zt2n-cdfc6fd6c" "namespace"="md-test" "machine"="md-5zt2n-cdfc6fd6c-gnn25"
I0712 18:50:22.671152   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0712 18:50:22.671209   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" 
I0712 18:50:22.682995   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-5zt2n-74d45c49c5-nz7cp\"" "machineset"="md-5zt2n-74d45c49c5" "namespace"="md-test" 
E0712 18:50:22.758591   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-nz7cp-jzmvk, got []"  "node"="md-5zt2n-74d45c49c5-nz7cp-jzmvk"
E0712 18:50:22.862688   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-nz7cp-jzmvk, got []"  "node"="md-5zt2n-74d45c49c5-nz7cp-jzmvk"
E0712 18:50:22.862742   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-5zt2n-74d45c49c5-nz7cp-jzmvk, got []"  "node"="md-5zt2n-74d45c49c5-nz7cp-jzmvk"
I0712 18:50:22.885335   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-5zt2n-74d45c49c5,md-5zt2n-cdfc6fd6c;Worker machines: md-5zt2n-74d45c49c5-frpbh,md-5zt2n-74d45c49c5-pvmtj,md-5zt2n-cdfc6fd6c-4nxs2,md-5zt2n-74d45c49c5-nz7cp,md-5zt2n-6657c7fddb-76zjz,md-5zt2n-6657c7fddb-56b6d,md-5zt2n-cdfc6fd6c-gnn25" "indirect descendants count"=9
•I0712 18:50:22.890311   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-5zt2n-74d45c49c5,md-5zt2n-cdfc6fd6c;Worker machines: md-5zt2n-6657c7fddb-76zjz,md-5zt2n-6657c7fddb-56b6d,md-5zt2n-cdfc6fd6c-gnn25,md-5zt2n-74d45c49c5-frpbh,md-5zt2n-74d45c49c5-pvmtj,md-5zt2n-cdfc6fd6c-4nxs2,md-5zt2n-74d45c49c5-nz7cp" "indirect descendants count"=9
I0712 18:50:22.961782   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-mbcvl" "namespace"="ms-test" "creating"=2 "need"=2
I0712 18:50:22.961830   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-mbcvl" "namespace"="ms-test" 
I0712 18:50:22.981483   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-mbcvl-mrnbg\"" "machineset"="ms-mbcvl" "namespace"="ms-test" 
I0712 18:50:22.981556   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-mbcvl" "namespace"="ms-test" 
I0712 18:50:22.999614   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-mbcvl-p8lkq\"" "machineset"="ms-mbcvl" "namespace"="ms-test" 
I0712 18:50:23.104904   10456 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-mbcvl" "namespace"="ms-test" "creating"=1 "need"=2
I0712 18:50:23.104968   10456 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-mbcvl" "namespace"="ms-test" 
I0712 18:50:23.121403   10456 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-mbcvl-b7vrz\"" "machineset"="ms-mbcvl" "namespace"="ms-test" 
E0712 18:50:23.219673   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-mbcvl-mrnbg-hlb4q, got []"  "node"="ms-mbcvl-mrnbg-hlb4q"
E0712 18:50:23.324064   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-mbcvl-mrnbg-hlb4q, got []"  "node"="ms-mbcvl-mrnbg-hlb4q"
E0712 18:50:23.324105   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-mbcvl-mrnbg-hlb4q, got []"  "node"="ms-mbcvl-mrnbg-hlb4q"
E0712 18:50:23.350935   10456 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-mbcvl-mrnbg-hlb4q for machine ms-test/ms-mbcvl-mrnbg: the cache is not started, can not read objects" "machineset"="ms-mbcvl" "namespace"="ms-test" 
E0712 18:50:23.355826   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-mbcvl-b7vrz-lqtd8, got []"  "node"="ms-mbcvl-b7vrz-lqtd8"
E0712 18:50:23.459613   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-mbcvl-b7vrz-lqtd8, got []"  "node"="ms-mbcvl-b7vrz-lqtd8"
E0712 18:50:23.459675   10456 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-mbcvl-b7vrz-lqtd8, got []"  "node"="ms-mbcvl-b7vrz-lqtd8"
I0712 18:50:23.582201   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-mbcvl-mrnbg,ms-mbcvl-b7vrz" "indirect descendants count"=2
I0712 18:50:23.585880   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-mbcvl-mrnbg,ms-mbcvl-b7vrz" "indirect descendants count"=2
•I0712 18:50:23.626832   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-5zt2n-cdfc6fd6c-gnn25" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-5zt2n-cdfc6fd6c-gnn25-cb4sf"}
E0712 18:50:23.686543   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-pvmtj\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-pvmtj" "namespace"="md-test"
•E0712 18:50:23.717341   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-8vr4p\" not found" "controller"="cluster" "name"="test1-8vr4p" "namespace"="default"
E0712 18:50:24.715016   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-frpbh\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-frpbh" "namespace"="md-test"
•I0712 18:50:24.841568   10456 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-x72vf" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0712 18:50:24.963011   10456 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-x72vf" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0712 18:50:24.967143   10456 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-x72vf" "namespace"="default"
I0712 18:50:25.721230   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:25.721275   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:25.724931   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:25.724965   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
E0712 18:50:25.729032   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
E0712 18:50:25.983443   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
•I0712 18:50:26.830731   10456 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-5zt2n-cdfc6fd6c-gnn25" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-5zt2n-cdfc6fd6c-gnn25-cb4sf"}
E0712 18:50:26.858419   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-5zt2n-cdfc6fd6c-gnn25\" not found" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-gnn25" "namespace"="md-test"
E0712 18:50:26.996962   10456 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-k2ldr/test-cluster-r8bpl"
E0712 18:50:27.016138   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-tfm6t\" not found" "controller"="cluster" "name"="test3-tfm6t" "namespace"="default"
E0712 18:50:27.864367   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-pvmtj\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-pvmtj" "namespace"="md-test"
E0712 18:50:28.017175   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:28.870369   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-frpbh\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-frpbh" "namespace"="md-test"
I0712 18:50:29.029965   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-5zt2n-74d45c49c5,md-5zt2n-cdfc6fd6c;Worker machines: md-5zt2n-6657c7fddb-56b6d,md-5zt2n-74d45c49c5-frpbh,md-5zt2n-74d45c49c5-pvmtj,md-5zt2n-cdfc6fd6c-4nxs2,md-5zt2n-74d45c49c5-nz7cp,md-5zt2n-6657c7fddb-76zjz" "indirect descendants count"=8
E0712 18:50:29.030427   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
•E0712 18:50:29.877529   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
I0712 18:50:30.031022   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-mbcvl-mrnbg,ms-mbcvl-b7vrz" "indirect descendants count"=2
E0712 18:50:30.035470   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
I0712 18:50:30.883806   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:30.883872   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:30.889443   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:30.889524   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
E0712 18:50:30.997353   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-pvmtj\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-pvmtj" "namespace"="md-test"
E0712 18:50:31.036532   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:32.006318   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-frpbh\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-frpbh" "namespace"="md-test"
E0712 18:50:32.132804   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
•E0712 18:50:33.006900   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-5zrqg\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-5zrqg" "namespace"="test-mhc-hvnv4"
E0712 18:50:33.133610   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:34.012968   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
E0712 18:50:34.134569   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
E0712 18:50:35.013553   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-bplz7\" for machine \"test-mhc-machine-zms4k\" in namespace \"test-mhc-hvnv4\": Cluster.cluster.x-k8s.io \"test-cluster-bplz7\" not found" "controller"="machine" "name"="test-mhc-machine-zms4k" "namespace"="test-mhc-hvnv4"
E0712 18:50:35.147452   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:36.042991   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-pvmtj\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-pvmtj" "namespace"="md-test"
I0712 18:50:36.148189   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-5zt2n-74d45c49c5,md-5zt2n-cdfc6fd6c;Worker machines: md-5zt2n-74d45c49c5-pvmtj,md-5zt2n-cdfc6fd6c-4nxs2,md-5zt2n-6657c7fddb-76zjz,md-5zt2n-6657c7fddb-56b6d,md-5zt2n-74d45c49c5-nz7cp,md-5zt2n-74d45c49c5-frpbh" "indirect descendants count"=8
E0712 18:50:36.148707   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
I0712 18:50:37.049850   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:37.049898   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:37.055572   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:37.055653   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
E0712 18:50:37.061372   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-frpbh\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-frpbh" "namespace"="md-test"
I0712 18:50:37.149284   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-mbcvl-mrnbg,ms-mbcvl-b7vrz" "indirect descendants count"=2
E0712 18:50:37.151041   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:38.067473   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
E0712 18:50:38.152149   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
E0712 18:50:39.093742   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-pvmtj\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-pvmtj" "namespace"="md-test"
E0712 18:50:39.152961   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:40.100128   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-frpbh\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-frpbh" "namespace"="md-test"
E0712 18:50:40.153836   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
I0712 18:50:41.106080   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:41.106137   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:41.111185   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:41.111244   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
E0712 18:50:41.117120   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
E0712 18:50:41.154844   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
I0712 18:50:42.133781   10456 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-t52kw" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0712 18:50:42.144382   10456 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-t52kw" "namespace"="default" 
E0712 18:50:42.156615   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:42.168491   10456 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-t52kw" "namespace"="default"
I0712 18:50:43.157495   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-5zt2n-74d45c49c5,md-5zt2n-cdfc6fd6c;Worker machines: md-5zt2n-6657c7fddb-56b6d,md-5zt2n-74d45c49c5-nz7cp,md-5zt2n-74d45c49c5-frpbh,md-5zt2n-74d45c49c5-pvmtj,md-5zt2n-cdfc6fd6c-4nxs2,md-5zt2n-6657c7fddb-76zjz" "indirect descendants count"=8
E0712 18:50:43.158019   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
E0712 18:50:43.174019   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-pvmtj\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-pvmtj" "namespace"="md-test"
I0712 18:50:44.158747   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-mbcvl-mrnbg,ms-mbcvl-b7vrz" "indirect descendants count"=2
E0712 18:50:44.159472   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
E0712 18:50:44.180499   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-74d45c49c5-frpbh\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-74d45c49c5-frpbh" "namespace"="md-test"
E0712 18:50:45.160391   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-x72vf: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-x72vf" "namespace"="default"
E0712 18:50:45.186258   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-5zt2n-cdfc6fd6c-4nxs2\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-5zt2n-cdfc6fd6c-4nxs2" "namespace"="md-test"
E0712 18:50:46.161396   10456 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-vnw79: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-vnw79" "namespace"="default"
I0712 18:50:46.191520   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:46.191568   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-76zjz" "namespace"="md-test" 
I0712 18:50:46.198059   10456 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:46.198131   10456 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-5zt2n-6657c7fddb-56b6d" "namespace"="md-test" 
I0712 18:50:46.217252   10456 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-t52kw" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0712 18:50:46.217660   10456 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-t52kw" "namespace"="default" "noderef"="id-node-1"
E0712 18:50:46.232846   10456 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-t52kw" "namespace"="default"

------------------------------
• [SLOW TEST:15.078 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
  /home/prow/go/src/sigs.k8s.io/cluster-api/controllers/cluster_controller_test.go:248
------------------------------


Ran 16 of 16 Specs in 26.589 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (26.59s)
PASS
Tearing down test suite
I0712 18:50:47.223047   10456 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-x6bqf" "namespace"="default" "count"=1
I0712 18:50:47.223102   10456 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-x6bqf" "namespace"="default" "descendants"="Control plane machines: test6-t52kw" "indirect descendants count"=0
E0712 18:50:47.223163   10456 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 18:50:47.223207   10456 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-881973133/tls.crt: no such file or directory"  
I0712 18:50:47.223231   10456 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0712 18:50:47.223261   10456 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0712 18:50:47.223300   10456 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0712 18:50:47.223311   10456 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0712 18:50:47.223336   10456 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0712 18:50:47.223316   10456 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0712 18:50:47.223352   10456 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0712 18:50:47.250891   10456 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:38889/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1254&timeout=10s&timeoutSeconds=504&watch=true: dial tcp 127.0.0.1:38889: connect: connection refused
E0712 18:50:47.251053   10456 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:38889/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1254&timeout=10s&timeoutSeconds=593&watch=true: dial tcp 127.0.0.1:38889: connect: connection refused
E0712 18:50:47.251165   10456 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:38889/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1254&timeout=10s&timeoutSeconds=576&watch=true: dial tcp 127.0.0.1:38889: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	84.432s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 261 lines ...
I0712 18:49:34.226871   10925 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0712 18:49:34.263038   10925 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":{}}}
I0712 18:49:34.463393   10925 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0712 18:49:34.463458   10925 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0712 18:49:34.600924   10925 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0712 18:49:35.043791   10925 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0712 18:49:37.083364   10925 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-rhsb6/test-cluster"
•E0712 18:49:37.535780   10925 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-bmg68/test-cluster"
•E0712 18:49:38.073920   10925 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:40113/?timeout=50ms: dial tcp 127.0.0.1:40113: connect: connection refused"  "cluster"="cluster-cache-test-mff4c/test-cluster"
•I0712 18:49:38.292686   10925 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}}}
I0712 18:49:38.394073   10925 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0712 18:49:38.394146   10925 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•E0712 18:49:38.578230   10925 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
I0712 18:49:38.578278   10925 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0712 18:49:38.578291   10925 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-470956334/tls.crt: no such file or directory"  
I0712 18:49:38.578304   10925 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0712 18:49:38.624445   10925 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:46501/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=143&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:46501: connect: connection refused


Ran 5 of 5 Specs in 14.060 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (14.06s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	14.237s
?   	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
I0712 18:49:44.113658   11605 controller.go:129]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0712 18:49:44.114850   11605 controller.go:125]  "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
I0712 18:49:44.115405   11605 controller.go:135]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0712 18:49:44.115549   11605 controller.go:135]  "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
I0712 18:49:55.550570   11605 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
I0712 18:49:55.550745   11605 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: 1626115772
Will run 1 of 1 specs

E0712 18:49:55.595130   11605 controller.go:125]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-0isynp\" not found" "kubeadmControlPlane"="kcp-foo-0isynp" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.041 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.04s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0712 18:49:55.596551   11605 controller.go:245]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-m1z5pl" "kubeadmControlPlane"="kcp-foo-m1z5pl" "namespace"="test" 
I0712 18:49:56.437523   11605 controller.go:330]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-m1z5pl" "kubeadmControlPlane"="kcp-foo-m1z5pl" "namespace"="test" "needRollout"=["kcp-foo-m1z5pl-mpdpv"]
I0712 18:49:56.437723   11605 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-m1z5pl" "kubeadmControlPlane"="kcp-foo-m1z5pl" "namespace"="test" "failures"="[machine kcp-foo-m1z5pl-69bmw does not have APIServerPodHealthy condition, machine kcp-foo-m1z5pl-69bmw does not have ControllerManagerPodHealthy condition, machine kcp-foo-m1z5pl-69bmw does not have SchedulerPodHealthy condition, machine kcp-foo-m1z5pl-69bmw does not have EtcdPodHealthy condition, machine kcp-foo-m1z5pl-69bmw does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (0.84s)
... skipping 60 lines ...
==================================
Random Seed: 1626115771
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.001 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestControlPlane (0.00s)
=== RUN   TestHasUnhealthyMachine
--- PASS: TestHasUnhealthyMachine (0.00s)
=== RUN   TestNewFailureDomainPicker
=== RUN   TestNewFailureDomainPicker/simple
=== RUN   TestNewFailureDomainPicker/no_machines
... skipping 111 lines ...
=======================================
Random Seed: 1626115771
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 271 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
E0712 18:49:43.143591   11518 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"  
E0712 18:49:51.466679   11518 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"  
E0712 18:50:00.452708   11518 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"  
E0712 18:50:11.583006   11518 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"  
E0712 18:50:28.056311   11518 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"  
E0712 18:50:41.065055   11518 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"  
E0712 18:50:58.712624   11518 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"  
E0712 18:51:19.636079   11518 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"  
E0712 18:51:50.652824   11518 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"  
E0712 18:52:35.810045   11518 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 71 lines ...
=== RUN   TestClusterStatus/returns_cluster_status
=== 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
E0712 18:52:35.816308   11518 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 18:52:35.816350   11518 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-143024772/tls.crt: no such file or directory"  
E0712 18:52:35.816361   11518 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 18:52:35.816371   11518 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-143024772/tls.crt: no such file or directory"  
I0712 18:52:35.816396   11518 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	184.310s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
... skipping 288 lines ...
I0712 18:49:51.009938   11872 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" 
I0712 18:49:51.009976   11872 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0712 18:49:51.109951   11872 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0712 18:49:51.210368   11872 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0712 18:49:51.210452   11872 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0712 18:49:51.293164   11872 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-4jfs55"} 
E0712 18:49:51.328442   11872 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"
•I0712 18:49:52.386645   11872 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-hh0tn4"} 
E0712 18:49:52.421474   11872 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.087 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
E0712 18:50:03.515715   11872 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"
E0712 18:50:04.643413   11872 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"
E0712 18:50:05.669020   11872 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"
••I0712 18:50:06.689852   11872 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0712 18:50:06.689928   11872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0712 18:50:06.689862   11872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
E0712 18:50:06.703434   11872 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"



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 27.567 seconds
FAIL! -- 4 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestAPIs (27.57s)
FAIL
FAIL	sigs.k8s.io/cluster-api/exp/addons/controllers	27.657s
?   	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.01s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0712 18:49:44.399714   12068 machinepool_controller_phases.go:237]  "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
=== RUN   TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused
--- PASS: TestReconcileMachinePoolInfrastructure (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestMachinePoolFinalizer
... skipping 96 lines ...
I0712 18:49:54.867097   12068 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0712 18:49:54.907707   12068 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••I0712 18:49:54.910720   12068 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 10.519 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (10.52s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	10.721s
?   	sigs.k8s.io/cluster-api/exp/util	[no test files]
?   	sigs.k8s.io/cluster-api/feature	[no test files]
?   	sigs.k8s.io/cluster-api/hack/boilerplate/test	[no test files]
... skipping 266 lines ...
--- PASS: TestGetFirstReasonAndMessage (0.00s)
=== RUN   TestNewConditionsGroup
--- PASS: TestNewConditionsGroup (0.00s)
=== RUN   TestMergeRespectPriority
=== RUN   TestMergeRespectPriority/aggregate_nil_list_return_nil
=== RUN   TestMergeRespectPriority/aggregate_empty_list_return_nil
=== RUN   TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error
=== RUN   TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning
=== RUN   TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info
=== RUN   TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info
=== RUN   TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown
=== RUN   TestMergeRespectPriority/nil_conditions_are_ignored
--- PASS: TestMergeRespectPriority (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_nil_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_empty_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown (0.00s)
    --- PASS: TestMergeRespectPriority/nil_conditions_are_ignored (0.00s)
=== RUN   TestNewPatch
=== RUN   TestNewPatch/No_changes_return_empty_patch
... skipping 204 lines ...
I0712 18:50:14.426273   15032 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=33559
I0712 18:50:14.426326   15032 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••I0712 18:50:15.246823   15032 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


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