periodic-cluster-api-test-release-0-3 #1593810120213532672
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 4m25s |
| Revision | release-0.3 |
... skipping 773 lines ... I1119 03:37:10.922800 8550 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset" I1119 03:37:10.923603 8550 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server" I1119 03:37:10.924891 8550 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate" I1119 03:37:10.925250 8550 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" I1119 03:37:10.925625 8550 server.go:199] controller-runtime/webhook "msg"="serving webhook server" "host"="" "port"=34563 I1119 03:37:11.501611 8550 kubeadmconfig_controller.go:223] "msg"="Cluster infrastructure is not ready, waiting" "kind"="Machine" "kubeadmconfig"={"Namespace":"default","Name":"my-machine-config"} "name"="my-machine" "version"="109" [32m•[0mE1119 03:37:11.531925 8550 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:37:11.531984 8550 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-783188048/tls.crt: no such file or directory" I1119 03:37:11.531993 8550 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E1119 03:37:11.532006 8550 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:37:11.532028 8550 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-783188048/tls.crt: no such file or directory" [1m[32mRan 1 of 1 Specs in 14.217 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (14.22s) PASS ok sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers 48.264s === RUN TestNewInitControlPlaneAdditionalFileEncodings --- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s) === RUN TestNewInitControlPlaneCommands ... skipping 316 lines ... === RUN Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined --- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s) --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s) --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s) === RUN Test_clusterctlClient_GetProviderComponents === RUN Test_clusterctlClient_GetProviderComponents/Pass === RUN Test_clusterctlClient_GetProviderComponents/Fail --- PASS: Test_clusterctlClient_GetProviderComponents (0.00s) --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s) --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s) === RUN Test_getComponentsByName_withEmptyVariables --- PASS: Test_getComponentsByName_withEmptyVariables (0.01s) === RUN Test_clusterctlClient_templateOptionsToVariables === RUN Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options) === RUN Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables) === RUN Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts) ... skipping 1398 lines ... I1119 03:36:55.701231 10555 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1 I1119 03:36:55.701479 10555 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":{}}} I1119 03:36:55.701530 10555 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}} I1119 03:36:55.701558 10555 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" I1119 03:36:55.701590 10555 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I1119 03:36:55.702512 10555 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1 2022/11/19 03:36:55 http: TLS handshake error from 127.0.0.1:42604: EOF === RUN TestClusterReconcilePhases === RUN TestClusterReconcilePhases/reconcile_infrastructure === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil === RUN TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref I1119 03:36:55.802311 10555 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" I1119 03:36:55.805328 10555 cluster_controller_phases.go:76] "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test" ... skipping 105 lines ... --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s) === RUN TestReconcileInfrastructure === RUN TestReconcileInfrastructure/new_machine,_infrastructure_config_ready I1119 03:36:55.857089 10555 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 I1119 03:36:55.858771 10555 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" E1119 03:36:55.859105 10555 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 I1119 03:36:55.859598 10555 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 I1119 03:36:56.285393 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={} E1119 03:36:56.287788 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" I1119 03:36:56.298375 10555 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine" I1119 03:36:56.298462 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}} I1119 03:36:56.408028 10555 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine" I1119 03:36:56.408125 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}} I1119 03:36:56.508597 10555 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" "noderef"="node-1" E1119 03:36:56.543950 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" E1119 03:36:56.544004 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="node-1" E1119 03:36:56.582362 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-mzv95\" in namespace \"test-machine-watches-mxm5w\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" E1119 03:36:57.586828 10555 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-mzv95\" in namespace \"test-machine-watches-mxm5w\", requeuing: requeue in 1s" E1119 03:36:57.592973 10555 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-mzv95\" in namespace \"test-machine-watches-mxm5w\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-mzv95\" in namespace \"test-machine-watches-mxm5w\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" --- PASS: TestWatches (1.76s) === 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 I1119 03:36:57.719657 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-bxzg6" "namespace"="test-machine-watches-mxm5w" "count"=1 I1119 03:36:57.719728 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-bxzg6" "namespace"="test-machine-watches-mxm5w" "descendants"="Worker machines: machine-created-mzv95" "indirect descendants count"=0 I1119 03:36:57.755989 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-bxzg6" "namespace"="test-machine-watches-mxm5w" "count"=1 I1119 03:36:57.756054 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-bxzg6" "namespace"="test-machine-watches-mxm5w" "descendants"="Worker machines: machine-created-mzv95" "indirect descendants count"=0 I1119 03:36:58.593509 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-bxzg6" "machine"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"c8433d05-4f93-469a-89cd-3a139cc2b3b6","apiVersion":"v1"} E1119 03:36:58.725865 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-mzv95\" not found" "controller"="machine" "name"="machine-created-mzv95" "namespace"="test-machine-watches-mxm5w" E1119 03:36:59.787931 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-pdzqp\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-ggfjc\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-ggfjc: secrets \"machine-reconcile-ggfjc-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-pdzqp" "namespace"="default" I1119 03:37:00.788509 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-ggfjc" "machine"="machine-created-pdzqp" "namespace"="default" "cause"="noderef is nil" "node"=null I1119 03:37:00.822828 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-ggfjc" "machine"="machine-created-pdzqp" "namespace"="default" "cause"="noderef is nil" "node"=null I1119 03:37:00.853948 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-ggfjc" "machine"="machine-created-pdzqp" "namespace"="default" "cause"="noderef is nil" "node"=null E1119 03:37:00.895552 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-pdzqp\" not found" "controller"="machine" "name"="machine-created-pdzqp" "namespace"="default" --- PASS: TestMachine_Reconcile (3.29s) --- PASS: TestMachine_Reconcile/reconcile_create (3.29s) === 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 13 lines ... --- 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) --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s) === RUN TestReconcileRequest === RUN TestReconcileRequest/machine_should_be_created I1119 03:37:00.930712 10555 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="created" "namespace"="default" "err"="cannot create a metadata client without a rest config" E1119 03:37:00.937021 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-ggfjc\" not found" "controller"="cluster" "name"="machine-reconcile-ggfjc" "namespace"="default" === RUN TestReconcileRequest/machine_should_be_updated I1119 03:37:00.964803 10555 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="updated" "namespace"="default" "err"="cannot create a metadata client without a rest config" === RUN TestReconcileRequest/machine_should_be_deleted I1119 03:37:00.970097 10555 machine_controller.go:305] "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="deleted" "namespace"="default" "cause"="noderef is nil" "node"=null --- PASS: TestReconcileRequest (0.04s) --- PASS: TestReconcileRequest/machine_should_be_created (0.03s) ... skipping 112 lines ... --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s) === RUN TestMachineHealthCheck_Reconcile === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist I1119 03:37:01.227740 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9r5qw" "namespace"="test-mhc-qbmg8" I1119 03:37:01.259224 10555 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 E1119 03:37:01.260312 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-8759z\" not found" "cluster"="test-mhc-qbmg8/test-cluster-8759z" E1119 03:37:01.275535 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-9r5qw\" not found" "controller"="machinehealthcheck" "name"="test-mhc-9r5qw" "namespace"="test-mhc-qbmg8" === 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 error cannot retrieve mhc in ctx: MachineHealthCheck.cluster.x-k8s.io "test-mhc-k97kb" not foundI1119 03:37:02.275865 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9r5qw" "namespace"="test-mhc-qbmg8" I1119 03:37:02.275985 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6kd9p" "namespace"="test-mhc-sprch" I1119 03:37:02.276022 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wch6g" "namespace"="test-mhc-h8zm8" I1119 03:37:02.276056 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-k97kb" "namespace"="test-mhc-769g7" I1119 03:37:02.289993 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I1119 03:37:02.416582 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-k97kb" "namespace"="test-mhc-769g7" I1119 03:37:02.528592 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-k97kb" "namespace"="test-mhc-769g7" === RUN TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones E1119 03:37:02.587764 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-769g7/test-cluster-jzzfn" E1119 03:37:02.589474 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-jzzfn\" not found" "controller"="cluster" "name"="test-cluster-jzzfn" "namespace"="test-mhc-769g7" I1119 03:37:02.700980 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-scd5p" "namespace"="test-mhc-5hd49" I1119 03:37:02.721264 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I1119 03:37:02.740963 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-scd5p" "namespace"="test-mhc-5hd49" E1119 03:37:02.806420 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-5hd49/test-cluster-ffpvw" I1119 03:37:02.810832 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-scd5p" "namespace"="test-mhc-5hd49" === RUN TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy I1119 03:37:02.828650 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" inframachine created: test-mhc-machine-infra-fw759 I1119 03:37:02.854773 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-bz8mv I1119 03:37:02.882272 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.882654 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:02.896314 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.896648 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:02.905333 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.905747 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:02.922455 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.922851 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:02.928750 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.929083 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:02.941250 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.942051 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:02.947258 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.947590 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" E1119 03:37:02.958419 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pjm4p, got []" "node"="test-mhc-node-pjm4p" node created: test-mhc-node-pjm4p E1119 03:37:02.958971 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-pjm4p" I1119 03:37:02.961032 10555 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" "noderef"="test-mhc-node-pjm4p" E1119 03:37:02.965557 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pjm4p, got []" "node"="test-mhc-node-pjm4p" E1119 03:37:02.965615 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pjm4p, got []" "node"="test-mhc-node-pjm4p" E1119 03:37:02.967272 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-pjm4p" E1119 03:37:02.967310 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-pjm4p" I1119 03:37:02.969966 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" inframachine created: test-mhc-machine-infra-zjs6s machine created: test-mhc-machine-tjpqj I1119 03:37:02.992592 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:02.999324 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.000605 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" ... skipping 46 lines ... I1119 03:37:03.124393 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.126637 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.128832 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.130429 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.131491 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.133677 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.134100 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-tjpqj/" I1119 03:37:03.157645 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.158234 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-tjpqj/" I1119 03:37:03.167885 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.168265 10555 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-pj2cm/test-mhc-wnlkr/test-mhc-machine-tjpqj/" E1119 03:37:03.191692 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ds8q5, got []" "node"="test-mhc-node-ds8q5" node created: test-mhc-node-ds8q5 E1119 03:37:03.192330 10555 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine" "node"="test-mhc-node-ds8q5" I1119 03:37:03.207392 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.241679 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" Cleaning up nodes, machines and infra machines. I1119 03:37:03.243287 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.249452 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.249909 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:03.277814 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:03.278405 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-pj2cm/test-mhc-wnlkr/test-mhc-machine-bz8mv/" I1119 03:37:03.278849 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-pj2cm/test-mhc-wnlkr/test-mhc-machine-tjpqj/" E1119 03:37:03.288953 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-pj2cm/test-cluster-2lrdb" I1119 03:37:03.297174 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" E1119 03:37:03.297277 10555 machinehealthcheck_controller.go:128] controllers/MachineHealthCheck "msg"="Failed to fetch Cluster for MachineHealthCheck" "error"="Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "cluster"="test-cluster-2lrdb" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" E1119 03:37:03.297331 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machinehealthcheck" "name"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine E1119 03:37:03.404401 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" inframachine created: test-mhc-machine-infra-9hkvt machine created: test-mhc-machine-64l7p E1119 03:37:03.603302 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-machine-watches-mxm5w/machine-reconcile-bxzg6" I1119 03:37:04.297610 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wnlkr" "namespace"="test-mhc-pj2cm" I1119 03:37:04.297712 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:04.314743 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} E1119 03:37:04.404828 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:04.456541 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:04.458039 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:04.459133 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:04.461114 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:04.462808 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:04.464470 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 467 lines ... I1119 03:37:05.394008 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.395738 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.397447 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.399123 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.403424 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.406393 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:05.406534 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:05.409249 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.411392 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.413315 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.415111 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.416881 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:05.418616 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 456 lines ... I1119 03:37:06.390573 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.392879 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.406996 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.409411 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.411735 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.414595 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:06.425191 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:06.425529 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-64l7p/" I1119 03:37:06.441654 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.442031 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-64l7p/" node created: test-mhc-node-snlw4 E1119 03:37:06.451437 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-snlw4, got []" "node"="test-mhc-node-snlw4" I1119 03:37:06.460937 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" inframachine created: test-mhc-machine-infra-f6zd5 I1119 03:37:06.479611 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" machine created: test-mhc-machine-7cl7x I1119 03:37:06.485923 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:06.493140 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 332 lines ... I1119 03:37:07.406489 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.414226 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.416565 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.419571 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.421809 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.424084 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:07.429563 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:07.431679 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.434391 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.437069 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.439657 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.443033 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:07.445478 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 340 lines ... I1119 03:37:08.461764 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.464006 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.466310 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.468594 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.479650 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.482426 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:08.482902 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:08.486594 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.488262 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.489586 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.491318 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.492466 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:08.493664 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 317 lines ... I1119 03:37:09.482842 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.492612 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.498681 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.499882 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.502418 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.505086 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:09.506529 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:09.507214 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.507712 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-7cl7x/" I1119 03:37:09.518102 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.518615 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-7cl7x/" node created: test-mhc-node-8v4z5 E1119 03:37:09.609119 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-8v4z5, got []" "node"="test-mhc-node-8v4z5" I1119 03:37:09.619135 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" inframachine created: test-mhc-machine-infra-kf9qx I1119 03:37:09.641945 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" machine created: test-mhc-machine-bjdwq I1119 03:37:09.644252 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:09.650555 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 250 lines ... I1119 03:37:10.494094 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.496813 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.508369 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.512475 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.515174 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.520294 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:10.523703 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:10.524350 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.525786 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.528292 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.530883 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.533586 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:10.536252 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 304 lines ... I1119 03:37:11.564257 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.566917 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.568304 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.569321 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.572402 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.575367 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" E1119 03:37:11.576548 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:11.577042 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.578373 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.579917 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.581450 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.584779 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:11.586948 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" ... skipping 241 lines ... I1119 03:37:12.582257 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.587382 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.590116 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.595090 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.597638 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.600035 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.600583 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/" E1119 03:37:12.608354 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:12.611204 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.611738 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/" E1119 03:37:12.660678 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-lwwj2, got []" "node"="test-mhc-node-lwwj2" node created: test-mhc-node-lwwj2 Cleaning up nodes, machines and infra machines. I1119 03:37:12.669257 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.669836 10555 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-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/test-mhc-node-lwwj2" I1119 03:37:12.686919 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.687483 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/" Cleaning up nodes, machines and infra machines. I1119 03:37:12.701440 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.701970 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-64l7p/" I1119 03:37:12.723725 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/" I1119 03:37:12.749555 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.750181 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-64l7p/" I1119 03:37:12.750611 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-7cl7x/" I1119 03:37:12.765984 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/" I1119 03:37:12.772036 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" I1119 03:37:12.772617 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-64l7p/" I1119 03:37:12.773077 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-7cl7x/" I1119 03:37:12.773461 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-r6f4d/test-mhc-f2n5z/test-mhc-machine-bjdwq/" I1119 03:37:12.791318 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-v5svs" "namespace"="test-mhc-r6f4d" "count"=2 I1119 03:37:12.791407 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-v5svs" "namespace"="test-mhc-r6f4d" "descendants"="Worker machines: test-mhc-machine-64l7p,test-mhc-machine-7cl7x,test-mhc-machine-bjdwq" "indirect descendants count"=1 I1119 03:37:12.800027 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-v5svs" "namespace"="test-mhc-r6f4d" "count"=2 I1119 03:37:12.800088 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-v5svs" "namespace"="test-mhc-r6f4d" "descendants"="Worker machines: test-mhc-machine-64l7p,test-mhc-machine-7cl7x,test-mhc-machine-bjdwq" "indirect descendants count"=1 I1119 03:37:12.807513 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f2n5z" "namespace"="test-mhc-r6f4d" === RUN TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy ... skipping 6 lines ... I1119 03:37:12.923658 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:12.964999 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:13.046110 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:13.207210 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:13.528376 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:13.608974 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-v5svs" "machine"="test-mhc-machine-7cl7x" "namespace"="test-mhc-r6f4d" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-8v4z5"} E1119 03:37:13.658713 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-7cl7x\" not found" "controller"="machine" "name"="test-mhc-machine-7cl7x" "namespace"="test-mhc-r6f4d" I1119 03:37:14.169428 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:14.659510 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:15.450560 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:15.660057 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-v5svs" "machine"="test-mhc-machine-bjdwq" "namespace"="test-mhc-r6f4d" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-lwwj2"} E1119 03:37:15.716275 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-bjdwq\" not found" "controller"="machine" "name"="test-mhc-machine-bjdwq" "namespace"="test-mhc-r6f4d" I1119 03:37:16.717125 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-v5svs" "machine"="test-mhc-machine-64l7p" "namespace"="test-mhc-r6f4d" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-snlw4"} E1119 03:37:16.767237 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-64l7p\" not found" "controller"="machine" "name"="test-mhc-machine-64l7p" "namespace"="test-mhc-r6f4d" E1119 03:37:17.767693 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" E1119 03:37:17.813472 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-r6f4d/test-cluster-v5svs" I1119 03:37:18.011664 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.775536 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:18.789295 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:18.790112 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:18.802772 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q9n7p, got []" "node"="test-mhc-node-q9n7p" node created: test-mhc-node-q9n7p I1119 03:37:18.809071 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.810797 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" inframachine created: test-mhc-machine-infra-8s8bz machine created: test-mhc-machine-f95hk I1119 03:37:18.835587 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.847627 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.853161 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.854355 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.895607 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:18.976953 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:19.138321 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:19.460904 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:19.789746 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:20.102238 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.804058 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.811358 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.821267 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.840475 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.872574 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.881050 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:20.883227 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:20.911995 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" node created: test-mhc-node-v5x9b E1119 03:37:20.948368 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-v5x9b, got []" "node"="test-mhc-node-v5x9b" I1119 03:37:20.955854 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" inframachine created: test-mhc-machine-infra-f5gg8 I1119 03:37:20.969868 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" machine created: test-mhc-machine-c5mqq I1119 03:37:20.979280 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:20.993923 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:21.001229 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:21.383684 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:21.883567 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:22.894548 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:22.912824 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:22.929404 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:22.952354 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:22.962188 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:22.978350 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:22.982764 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" E1119 03:37:22.985282 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" E1119 03:37:23.004077 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-scwx4, got []" "node"="test-mhc-node-scwx4" node created: test-mhc-node-scwx4 Cleaning up nodes, machines and infra machines. I1119 03:37:23.019043 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:23.052103 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" I1119 03:37:23.062822 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chhjr" "namespace"="test-mhc-qbmlm" Cleaning up nodes, machines and infra machines. ... skipping 10 lines ... inframachine created: test-mhc-machine-infra-682dn I1119 03:37:23.166064 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-tp89c I1119 03:37:23.184978 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:23.192236 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:23.985865 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-m268w" "machine"="test-mhc-machine-nlwh7" "namespace"="test-mhc-qbmlm" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-q9n7p"} E1119 03:37:24.038338 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-nlwh7\" not found" "controller"="machine" "name"="test-mhc-machine-nlwh7" "namespace"="test-mhc-qbmlm" I1119 03:37:25.038921 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-m268w" "machine"="test-mhc-machine-f95hk" "namespace"="test-mhc-qbmlm" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-v5x9b"} E1119 03:37:25.092416 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-f95hk\" not found" "controller"="machine" "name"="test-mhc-machine-f95hk" "namespace"="test-mhc-qbmlm" I1119 03:37:26.092941 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-m268w" "machine"="test-mhc-machine-c5mqq" "namespace"="test-mhc-qbmlm" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-scwx4"} E1119 03:37:26.139086 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-c5mqq\" not found" "controller"="machine" "name"="test-mhc-machine-c5mqq" "namespace"="test-mhc-qbmlm" E1119 03:37:27.139488 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" E1119 03:37:28.120209 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-qbmlm/test-cluster-m268w" I1119 03:37:28.148765 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:28.160554 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" E1119 03:37:28.160735 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" E1119 03:37:28.195680 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gpkm4, got []" "node"="test-mhc-node-gpkm4" node created: test-mhc-node-gpkm4 I1119 03:37:28.203409 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" inframachine created: test-mhc-machine-infra-zjxgr machine created: test-mhc-machine-fv9x2 I1119 03:37:28.252173 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:28.259390 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.176742 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.190118 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.203854 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.211492 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.228790 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.236850 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.249394 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" E1119 03:37:29.256164 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bfpxn, got []" "node"="test-mhc-node-bfpxn" node created: test-mhc-node-bfpxn I1119 03:37:29.280202 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.282294 10555 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-fv9x2" "namespace"="test-mhc-vf9m6" "noderef"="test-mhc-node-bfpxn" inframachine created: test-mhc-machine-infra-trvhs machine created: test-mhc-machine-q6jwv I1119 03:37:29.314178 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" ... skipping 8 lines ... I1119 03:37:29.517917 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.530270 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" Cleaning up nodes, machines and infra machines. I1119 03:37:29.560289 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.573572 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.587884 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.588468 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-vf9m6/test-mhc-9c8f9/test-mhc-machine-tp89c/" I1119 03:37:29.593107 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nggwq" "machine"="test-mhc-machine-q6jwv" "namespace"="test-mhc-vf9m6" "cause"="noderef is nil" "node"=null I1119 03:37:29.627930 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:29.628603 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-vf9m6/test-mhc-9c8f9/test-mhc-machine-tp89c/" I1119 03:37:29.629030 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-vf9m6/test-mhc-9c8f9/test-mhc-machine-fv9x2/" E1119 03:37:29.667992 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-q6jwv\" not found" "controller"="machine" "name"="test-mhc-machine-q6jwv" "namespace"="test-mhc-vf9m6" I1119 03:37:29.674821 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nggwq" "namespace"="test-mhc-vf9m6" "count"=2 I1119 03:37:29.674913 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nggwq" "namespace"="test-mhc-vf9m6" "descendants"="Worker machines: test-mhc-machine-tp89c,test-mhc-machine-fv9x2" "indirect descendants count"=0 I1119 03:37:29.688793 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nggwq" "namespace"="test-mhc-vf9m6" "count"=2 I1119 03:37:29.688861 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nggwq" "namespace"="test-mhc-vf9m6" "descendants"="Worker machines: test-mhc-machine-tp89c,test-mhc-machine-fv9x2" "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-tvnq4 machine created: test-mhc-machine-x9jfv E1119 03:37:29.810324 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-9c8f9\" not found" "controller"="machinehealthcheck" "name"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:30.668479 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nggwq" "machine"="test-mhc-machine-tp89c" "namespace"="test-mhc-vf9m6" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-gpkm4"} E1119 03:37:30.719418 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tp89c\" not found" "controller"="machine" "name"="test-mhc-machine-tp89c" "namespace"="test-mhc-vf9m6" I1119 03:37:30.810635 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:30.826081 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I1119 03:37:30.946455 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8f9" "namespace"="test-mhc-vf9m6" I1119 03:37:30.946532 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:30.947539 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:30.949320 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" ... skipping 390 lines ... I1119 03:37:31.768310 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.770600 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.785501 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.789575 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.791510 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.793522 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" E1119 03:37:31.793938 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fv9x2\" not found" "controller"="machine" "name"="test-mhc-machine-fv9x2" "namespace"="test-mhc-vf9m6" I1119 03:37:31.795320 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.797077 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.798810 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.800708 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.802525 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:31.804278 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" ... skipping 451 lines ... I1119 03:37:32.784850 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.786533 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.788242 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.789942 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.791781 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.793797 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" E1119 03:37:32.794347 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:32.795950 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.797722 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.799481 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.801283 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.803031 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:32.804787 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" ... skipping 435 lines ... I1119 03:37:33.793174 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.794981 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.796714 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.798665 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.809347 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.810190 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" E1119 03:37:33.817290 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:33.817813 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.821020 10555 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-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/" I1119 03:37:33.833926 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.834404 10555 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-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/" E1119 03:37:33.863059 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pcgtv, got []" "node"="test-mhc-node-pcgtv" node created: test-mhc-node-pcgtv E1119 03:37:33.863999 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pcgtv, got []" "node"="test-mhc-node-pcgtv" I1119 03:37:33.871318 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.886087 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.895247 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.895645 10555 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-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/test-mhc-node-pcgtv" I1119 03:37:33.914102 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.914671 10555 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-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/test-mhc-node-pcgtv" Cleaning up nodes, machines and infra machines. I1119 03:37:33.922585 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.923002 10555 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-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/test-mhc-node-pcgtv" I1119 03:37:33.925337 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.925672 10555 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-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/test-mhc-node-pcgtv" I1119 03:37:33.928049 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.928544 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/" I1119 03:37:33.945494 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k567n" "namespace"="test-mhc-8rbrc" "descendants"="Worker machines: test-mhc-machine-x9jfv" "indirect descendants count"=1 I1119 03:37:33.947446 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:33.947793 10555 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="NodeNotFound" "target"="test-mhc-8rbrc/test-mhc-zbgwx/test-mhc-machine-x9jfv/" I1119 03:37:33.952254 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k567n" "namespace"="test-mhc-8rbrc" "descendants"="Worker machines: test-mhc-machine-x9jfv" "indirect descendants count"=1 === RUN TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted I1119 03:37:33.957527 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zbgwx" "namespace"="test-mhc-8rbrc" I1119 03:37:34.157917 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" "creating"=1 "need"=1 I1119 03:37:34.157968 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:34.169868 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-pxtst-gtvjg\"" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:34.246568 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:34.267612 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} I1119 03:37:34.287915 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" E1119 03:37:34.702091 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-vf9m6/test-cluster-nggwq" I1119 03:37:34.817808 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-k567n" "machine"="test-mhc-machine-x9jfv" "namespace"="test-mhc-8rbrc" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-pcgtv"} E1119 03:37:34.860368 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x9jfv\" not found" "controller"="machine" "name"="test-mhc-machine-x9jfv" "namespace"="test-mhc-8rbrc" I1119 03:37:35.288125 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:35.871350 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:35.872478 10555 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:35.882473 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:35.883862 10555 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:35.893081 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" ... skipping 2 lines ... I1119 03:37:35.903675 10555 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:35.904958 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:35.905864 10555 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:35.914862 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:35.914918 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:36.289165 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:36.289655 10555 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-qzgqg/test-mhc-qlnkn/mhc-ms-pxtst-gtvjg/" I1119 03:37:36.297630 10555 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:36.304101 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:36.304157 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:36.305103 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:36.305462 10555 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-qzgqg/test-mhc-qlnkn/mhc-ms-pxtst-gtvjg/" I1119 03:37:36.311189 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:36.311463 10555 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" I1119 03:37:36.311546 10555 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-qzgqg/test-mhc-qlnkn/mhc-ms-pxtst-gtvjg/" I1119 03:37:36.321179 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:36.321229 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:36.374509 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-hs4tf" "namespace"="test-mhc-qzgqg" "count"=1 I1119 03:37:36.374570 10555 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-hs4tf" "namespace"="test-mhc-qzgqg" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-pxtst" I1119 03:37:36.376654 10555 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-pxtst" "namespace"="test-mhc-qzgqg" "machine"="mhc-ms-pxtst-gtvjg" I1119 03:37:36.383077 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hs4tf" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" "cause"="cluster is being deleted" "node"=null I1119 03:37:36.384535 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:36.384869 10555 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-qzgqg/test-mhc-qlnkn/mhc-ms-pxtst-gtvjg/" I1119 03:37:36.386412 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hs4tf" "namespace"="test-mhc-qzgqg" "descendants"="Machine sets: mhc-ms-pxtst;Worker machines: mhc-ms-pxtst-gtvjg" "indirect descendants count"=1 I1119 03:37:36.386496 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qlnkn" "namespace"="test-mhc-qzgqg" I1119 03:37:36.396223 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hs4tf" "namespace"="test-mhc-qzgqg" "descendants"="Worker machines: mhc-ms-pxtst-gtvjg" "indirect descendants count"=1 === RUN TestMachineHealthCheck_Reconcile/when_a_machine_is_paused === RUN TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created I1119 03:37:36.423379 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hs4tf" "machine"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" "cause"="cluster is being deleted" "node"=null E1119 03:37:36.473705 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-pxtst-gtvjg\" not found" "controller"="machine" "name"="mhc-ms-pxtst-gtvjg" "namespace"="test-mhc-qzgqg" I1119 03:37:36.478622 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" inframachine created: test-mhc-machine-infra-ht4rc I1119 03:37:36.495711 10555 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={} machine created: test-mhc-machine-dgg9b I1119 03:37:36.627709 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:36.636039 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" ... skipping 408 lines ... I1119 03:37:37.484805 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.486564 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.488689 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.492044 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.494748 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.496282 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" E1119 03:37:37.519039 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gt9x5, got []" "node"="test-mhc-node-gt9x5" E1119 03:37:37.519039 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gt9x5, got []" "node"="test-mhc-node-gt9x5" node created: test-mhc-node-gt9x5 E1119 03:37:37.519314 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gt9x5, got []" "node"="test-mhc-node-gt9x5" I1119 03:37:37.561166 10555 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-dgg9b" "namespace"="test-mhc-lcclw" "noderef"="test-mhc-node-gt9x5" I1119 03:37:37.562381 10555 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-dgg9b" "target"="test-mhc-lcclw/test-mhc-m7pzz/test-mhc-machine-dgg9b/" I1119 03:37:37.598056 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.623288 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.629842 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.636867 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.641027 10555 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-dgg9b" "target"="test-mhc-lcclw/test-mhc-m7pzz/test-mhc-machine-dgg9b/test-mhc-node-gt9x5" I1119 03:37:37.670856 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" Cleaning up nodes, machines and infra machines. I1119 03:37:37.688700 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.691648 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.696798 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7pzz" "namespace"="test-mhc-lcclw" I1119 03:37:37.704092 10555 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-tm6vv" "namespace"="test-mhc-lcclw" "count"=1 ... skipping 22 lines ... I1119 03:37:37.814899 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.822739 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.826743 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.828591 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.830520 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.832392 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" E1119 03:37:37.834223 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-dgg9b\" not found" "controller"="machine" "name"="test-mhc-machine-dgg9b" "namespace"="test-mhc-lcclw" I1119 03:37:37.834350 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.836110 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.837923 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.839979 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.842433 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:37.844811 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" ... skipping 491 lines ... I1119 03:37:38.838831 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.840800 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.843433 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.844072 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.845251 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.847300 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" E1119 03:37:38.847870 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" I1119 03:37:38.847937 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.852016 10555 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-gwhsq" "target"="test-mhc-r9qcw/test-mhc-7tq5g/test-mhc-machine-gwhsq/" node created: test-mhc-node-wh9hb E1119 03:37:38.881933 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wh9hb, got []" "node"="test-mhc-node-wh9hb" E1119 03:37:38.882126 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wh9hb, got []" "node"="test-mhc-node-wh9hb" E1119 03:37:38.882585 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wh9hb, got []" "node"="test-mhc-node-wh9hb" E1119 03:37:38.882643 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wh9hb, got []" "node"="test-mhc-node-wh9hb" I1119 03:37:38.888380 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.892707 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.912016 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.917529 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.930139 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.937657 10555 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-gwhsq" "target"="test-mhc-r9qcw/test-mhc-7tq5g/test-mhc-machine-gwhsq/test-mhc-node-wh9hb" I1119 03:37:38.966577 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" E1119 03:37:38.968905 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-8rbrc/test-cluster-k567n" I1119 03:37:38.972221 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:38.997965 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" Cleaning up nodes, machines and infra machines. I1119 03:37:39.009936 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:39.014963 10555 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-gwhsq" "target"="test-mhc-r9qcw/test-mhc-7tq5g/test-mhc-machine-gwhsq/" I1119 03:37:39.024388 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dbwcf" "namespace"="test-mhc-r9qcw" "descendants"="Worker machines: test-mhc-machine-gwhsq" "indirect descendants count"=1 I1119 03:37:39.031890 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dbwcf" "namespace"="test-mhc-r9qcw" "descendants"="Worker machines: test-mhc-machine-gwhsq" "indirect descendants count"=1 E1119 03:37:39.040586 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-7tq5g\" not found" "controller"="machinehealthcheck" "name"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" --- PASS: TestMachineHealthCheck_Reconcile (37.97s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.18s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.05s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.03s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (1.20s) --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.27s) ... skipping 10 lines ... --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s) machinehealthcheck_controller_test.go:933: skipping until made stable --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (1.32s) --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (1.32s) === RUN TestClusterToMachineHealthCheck === RUN TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster E1119 03:37:39.043732 10555 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 E1119 03:37:39.045088 10555 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 E1119 03:37:39.046482 10555 machinehealthcheck_controller.go:474] "msg"="expected a Node" "error"="incorrect type" "type"="handler.MapObject" === RUN TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node E1119 03:37:39.046666 10555 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 E1119 03:37:39.046946 10555 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 I1119 03:37:39.049550 10555 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine1/" I1119 03:37:39.050104 10555 machinehealthcheck_controller.go:387] "msg"="Target has failed health check, marking for remediation" "message"="" "reason"="" "target"="default/mhc/machine2/" E1119 03:37:39.051378 10555 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 E1119 03:37:39.061438 10555 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 E1119 03:37:39.063673 10555 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 73 lines ... I1119 03:37:39.368279 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3 I1119 03:37:39.368328 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" I1119 03:37:39.386058 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-6657c7fddb-scxqp\"" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" I1119 03:37:39.455497 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1 I1119 03:37:39.455547 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" I1119 03:37:39.469023 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-cdfc6fd6c-ggk9p\"" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" E1119 03:37:39.553274 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.553437 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.553930 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.656792 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.656841 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.656871 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.656919 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.656871 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.656968 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj, got []" "node"="md-9fmbd-cdfc6fd6c-ggk9p-zd6fj" E1119 03:37:39.682512 10555 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-9fmbd-cdfc6fd6c-ggk9p-zd6fj for machine md-test/md-9fmbd-cdfc6fd6c-ggk9p: the cache is not started, can not read objects" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" I1119 03:37:39.725307 10555 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2 I1119 03:37:39.725351 10555 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I1119 03:37:39.732933 10555 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "machine"="md-9fmbd-6657c7fddb-r9zlb" I1119 03:37:39.843112 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2 I1119 03:37:39.843199 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" I1119 03:37:39.848352 10555 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-dbwcf" "machine"="test-mhc-machine-gwhsq" "namespace"="test-mhc-r9qcw" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-wh9hb"} I1119 03:37:39.853876 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-cdfc6fd6c-jcqf9\"" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" E1119 03:37:39.891694 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gwhsq\" not found" "controller"="machine" "name"="test-mhc-machine-gwhsq" "namespace"="test-mhc-r9qcw" E1119 03:37:39.892335 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.892346 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.892416 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.997712 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.997765 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.997779 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.997804 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.998603 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" E1119 03:37:39.998653 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-jcqf9-tqfgt, got []" "node"="md-9fmbd-cdfc6fd6c-jcqf9-tqfgt" I1119 03:37:40.040872 10555 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7tq5g" "namespace"="test-mhc-r9qcw" I1119 03:37:40.049220 10555 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1 I1119 03:37:40.049269 10555 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I1119 03:37:40.059001 10555 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "machine"="md-9fmbd-6657c7fddb-nmgcn" I1119 03:37:40.169070 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3 I1119 03:37:40.169112 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" I1119 03:37:40.183424 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-cdfc6fd6c-8gqrr\"" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" E1119 03:37:40.261248 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.261254 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.261254 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.264443 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.264511 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.264575 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.264630 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.264682 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" E1119 03:37:40.264725 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-cdfc6fd6c-8gqrr-f8m4r, got []" "node"="md-9fmbd-cdfc6fd6c-8gqrr-f8m4r" I1119 03:37:40.327057 10555 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0 I1119 03:37:40.327100 10555 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "delete-policy"="Random" I1119 03:37:40.330984 10555 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-9fmbd-6657c7fddb" "namespace"="md-test" "machine"="md-9fmbd-6657c7fddb-scxqp" I1119 03:37:40.575385 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1 I1119 03:37:40.575428 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" I1119 03:37:40.588998 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-74d45c49c5-s7kfr\"" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" E1119 03:37:40.667923 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.668045 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.668099 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.770813 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.770852 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.771068 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.771088 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.771167 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" E1119 03:37:40.771216 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-s7kfr-pq8xr, got []" "node"="md-9fmbd-74d45c49c5-s7kfr-pq8xr" I1119 03:37:40.806611 10555 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2 I1119 03:37:40.806645 10555 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" I1119 03:37:40.812660 10555 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "machine"="md-9fmbd-cdfc6fd6c-jcqf9" E1119 03:37:40.892041 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" I1119 03:37:40.923094 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2 I1119 03:37:40.923247 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" I1119 03:37:40.932897 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-74d45c49c5-gch7f\"" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" E1119 03:37:41.001932 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.001932 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.002324 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.005190 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.005282 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.005356 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.005396 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.005406 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" E1119 03:37:41.005422 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-gch7f-597n6, got []" "node"="md-9fmbd-74d45c49c5-gch7f-597n6" I1119 03:37:41.037368 10555 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1 I1119 03:37:41.037405 10555 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random" I1119 03:37:41.041247 10555 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-9fmbd-cdfc6fd6c" "namespace"="md-test" "machine"="md-9fmbd-cdfc6fd6c-8gqrr" I1119 03:37:41.150597 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3 I1119 03:37:41.150638 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" I1119 03:37:41.161940 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-9fmbd-74d45c49c5-lbcqb\"" "machineset"="md-9fmbd-74d45c49c5" "namespace"="md-test" E1119 03:37:41.280544 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.280908 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.281112 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.384659 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.384793 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.384655 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.384839 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.385644 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.385704 10555 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-9fmbd-74d45c49c5-lbcqb-q5p5z, got []" "node"="md-9fmbd-74d45c49c5-lbcqb-q5p5z" E1119 03:37:41.412228 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-qzgqg/test-cluster-hs4tf" I1119 03:37:41.413100 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-9fmbd-74d45c49c5,md-9fmbd-cdfc6fd6c;Worker machines: md-9fmbd-6657c7fddb-pr9g4,md-9fmbd-74d45c49c5-gch7f,md-9fmbd-74d45c49c5-lbcqb,md-9fmbd-74d45c49c5-s7kfr,md-9fmbd-cdfc6fd6c-ggk9p,md-9fmbd-6657c7fddb-x494k" "indirect descendants count"=8 [32m•[0mI1119 03:37:41.418261 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-9fmbd-74d45c49c5,md-9fmbd-cdfc6fd6c;Worker machines: md-9fmbd-74d45c49c5-lbcqb,md-9fmbd-74d45c49c5-s7kfr,md-9fmbd-cdfc6fd6c-ggk9p,md-9fmbd-6657c7fddb-x494k,md-9fmbd-6657c7fddb-pr9g4,md-9fmbd-74d45c49c5-gch7f" "indirect descendants count"=8 [32m•[0mE1119 03:37:41.537348 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-jb672\" not found" "controller"="cluster" "name"="test1-jb672" "namespace"="default" I1119 03:37:41.964956 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:41.964991 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:41.981194 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:37:41.981236 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" E1119 03:37:42.020708 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" [32m•[0mI1119 03:37:42.693962 10555 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-5lc77" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I1119 03:37:42.810167 10555 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-5lc77" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E1119 03:37:42.814376 10555 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-5lc77" "namespace"="default" E1119 03:37:43.048686 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" E1119 03:37:43.837809 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-lcclw/test-cluster-tm6vv" E1119 03:37:43.841088 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" [32m•[0mE1119 03:37:44.074310 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-gch7f\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-gch7f" "namespace"="md-test" E1119 03:37:44.855467 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-s5x5l\" not found" "controller"="cluster" "name"="test3-s5x5l" "namespace"="default" I1119 03:37:45.101799 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:45.101854 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:45.106410 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:37:45.106444 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" E1119 03:37:45.110967 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" E1119 03:37:45.856305 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" E1119 03:37:46.116676 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" E1119 03:37:46.880086 10555 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="test-mhc-r9qcw/test-cluster-dbwcf" E1119 03:37:46.880684 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" [32m•[0mE1119 03:37:47.121598 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-gch7f\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-gch7f" "namespace"="md-test" I1119 03:37:47.881238 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-9fmbd-74d45c49c5,md-9fmbd-cdfc6fd6c;Worker machines: md-9fmbd-6657c7fddb-x494k,md-9fmbd-6657c7fddb-pr9g4,md-9fmbd-74d45c49c5-gch7f,md-9fmbd-74d45c49c5-lbcqb,md-9fmbd-74d45c49c5-s7kfr,md-9fmbd-cdfc6fd6c-ggk9p" "indirect descendants count"=8 E1119 03:37:47.885456 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" E1119 03:37:48.130781 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" E1119 03:37:48.886222 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" I1119 03:37:49.135924 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:49.135979 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:49.141765 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:37:49.141806 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" E1119 03:37:49.146170 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" E1119 03:37:49.896535 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" [32m•[0mE1119 03:37:50.151395 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-gch7f\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-gch7f" "namespace"="md-test" E1119 03:37:50.897310 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" E1119 03:37:51.156559 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" E1119 03:37:51.898045 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" E1119 03:37:52.157170 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-tjpqj\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-tjpqj" "namespace"="test-mhc-pj2cm" E1119 03:37:52.907865 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" E1119 03:37:53.163304 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" E1119 03:37:53.908695 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" I1119 03:37:54.167837 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:54.167880 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:54.171915 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:37:54.171962 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" E1119 03:37:54.176467 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-gch7f\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-gch7f" "namespace"="md-test" I1119 03:37:54.909399 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-9fmbd-74d45c49c5,md-9fmbd-cdfc6fd6c;Worker machines: md-9fmbd-6657c7fddb-pr9g4,md-9fmbd-74d45c49c5-gch7f,md-9fmbd-74d45c49c5-lbcqb,md-9fmbd-74d45c49c5-s7kfr,md-9fmbd-cdfc6fd6c-ggk9p,md-9fmbd-6657c7fddb-x494k" "indirect descendants count"=8 E1119 03:37:54.910016 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" E1119 03:37:55.176874 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-2lrdb\" for machine \"test-mhc-machine-bz8mv\" in namespace \"test-mhc-pj2cm\": Cluster.cluster.x-k8s.io \"test-cluster-2lrdb\" not found" "controller"="machine" "name"="test-mhc-machine-bz8mv" "namespace"="test-mhc-pj2cm" E1119 03:37:55.910797 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" E1119 03:37:56.182089 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" E1119 03:37:56.911601 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" E1119 03:37:57.200784 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" E1119 03:37:57.912401 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" E1119 03:37:58.206389 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-gch7f\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-gch7f" "namespace"="md-test" E1119 03:37:58.913214 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" I1119 03:37:59.210585 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:59.210624 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:37:59.214368 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:37:59.214410 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" E1119 03:37:59.218934 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" E1119 03:37:59.913957 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" I1119 03:38:00.234240 10555 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-h4wcd" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" E1119 03:38:00.248606 10555 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-h4wcd" "namespace"="default" E1119 03:38:00.264666 10555 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-h4wcd" "namespace"="default" E1119 03:38:00.914897 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" E1119 03:38:01.270385 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" I1119 03:38:01.915706 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-9fmbd-74d45c49c5,md-9fmbd-cdfc6fd6c;Worker machines: md-9fmbd-74d45c49c5-s7kfr,md-9fmbd-cdfc6fd6c-ggk9p,md-9fmbd-6657c7fddb-x494k,md-9fmbd-6657c7fddb-pr9g4,md-9fmbd-74d45c49c5-gch7f,md-9fmbd-74d45c49c5-lbcqb" "indirect descendants count"=8 E1119 03:38:01.916442 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" E1119 03:38:02.275699 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-gch7f\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-gch7f" "namespace"="md-test" E1119 03:38:02.917302 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test-too\" for Cluster default/test2-5lc77: failed to retrieve external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-5lc77" "namespace"="default" E1119 03:38:03.280705 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-cdfc6fd6c-ggk9p\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-cdfc6fd6c-ggk9p" "namespace"="md-test" E1119 03:38:03.918257 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get \"test\" for Cluster default/test4-z5rrw: failed to retrieve external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-z5rrw" "namespace"="default" I1119 03:38:04.285542 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:38:04.285597 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-x494k" "namespace"="md-test" I1119 03:38:04.289939 10555 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:38:04.289989 10555 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-9fmbd-6657c7fddb-pr9g4" "namespace"="md-test" I1119 03:38:04.305941 10555 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-h4wcd" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)" I1119 03:38:04.306233 10555 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-h4wcd" "namespace"="default" "noderef"="id-node-1" E1119 03:38:04.319573 10555 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-h4wcd" "namespace"="default" [90m------------------------------[0m [32m• [SLOW TEST:15.065 seconds][0m Cluster Reconciler [90m/home/prow/go/src/sigs.k8s.io/cluster-api/controllers/cluster_controller_test.go:45[0m Should successfully set Status.ControlPlaneInitialized on the cluster object if controlplane is ready ... skipping 25 lines ... I1119 03:38:05.021425 10555 conversion.go:64] "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config" [32m•[0mI1119 03:38:05.022786 10555 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" I1119 03:38:05.023414 10555 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" I1119 03:38:05.023957 10555 machine_controller_phases.go:278] "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" I1119 03:38:05.023985 10555 machine_controller_noderef.go:45] "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" [32m•[0mI1119 03:38:05.024658 10555 machine_controller.go:327] "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" E1119 03:38:05.025891 10555 machine_controller.go:494] "msg"="Error creating a remote client while deleting Machine, won't retry" "error"="failed to create REST configuration for Cluster default/test-cluster: invalid configuration: no configuration has been provided" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" [32m•[0mI1119 03:38:05.099583 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-6j5tc" "namespace"="ms-test" "creating"=2 "need"=2 I1119 03:38:05.099624 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-6j5tc" "namespace"="ms-test" I1119 03:38:05.112833 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-6j5tc-btg86\"" "machineset"="ms-6j5tc" "namespace"="ms-test" I1119 03:38:05.112889 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-6j5tc" "namespace"="ms-test" I1119 03:38:05.128210 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-6j5tc-fv48w\"" "machineset"="ms-6j5tc" "namespace"="ms-test" I1119 03:38:05.233465 10555 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-6j5tc" "namespace"="ms-test" "creating"=1 "need"=2 I1119 03:38:05.233514 10555 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-6j5tc" "namespace"="ms-test" I1119 03:38:05.250517 10555 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-6j5tc-p96wz\"" "machineset"="ms-6j5tc" "namespace"="ms-test" E1119 03:38:05.325079 10555 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-9fmbd-74d45c49c5-s7kfr\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-9fmbd-74d45c49c5-s7kfr" "namespace"="md-test" E1119 03:38:05.481444 10555 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-6j5tc-p96wz-fh56x for machine ms-test/ms-6j5tc-p96wz: the cache is not started, can not read objects" "machineset"="ms-6j5tc" "namespace"="ms-test" I1119 03:38:05.604755 10555 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-6j5tc-p96wz,ms-6j5tc-fv48w" "indirect descendants count"=2 [32m•[0m [1m[32mRan 16 of 16 Specs in 26.542 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m16 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (26.54s) PASS Tearing down test suite E1119 03:38:05.608200 10555 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:38:05.608250 10555 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-527594821/tls.crt: no such file or directory" E1119 03:38:05.608265 10555 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:38:05.608277 10555 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-527594821/tls.crt: no such file or directory" I1119 03:38:05.608488 10555 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" I1119 03:38:05.608558 10555 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" I1119 03:38:05.608597 10555 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I1119 03:38:05.608616 10555 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" I1119 03:38:05.608526 10555 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I1119 03:38:05.608545 10555 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" I1119 03:38:05.608699 10555 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E1119 03:38:05.638636 10555 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:38603/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1295&timeout=10s&timeoutSeconds=393&watch=true: dial tcp 127.0.0.1:38603: connect: connection refused E1119 03:38:05.638653 10555 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:38603/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1295&timeout=10s&timeoutSeconds=579&watch=true: dial tcp 127.0.0.1:38603: connect: connection refused E1119 03:38:05.639046 10555 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:38603/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1295&timeout=10s&timeoutSeconds=522&watch=true: dial tcp 127.0.0.1:38603: connect: connection refused ok sigs.k8s.io/cluster-api/controllers 82.008s === RUN TestGetResourceFound --- PASS: TestGetResourceFound (0.00s) === RUN TestGetResourceNotFound --- PASS: TestGetResourceNotFound (0.01s) === RUN TestCloneTemplateResourceNotFound ... skipping 261 lines ... I1119 03:36:55.720160 10792 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" I1119 03:36:55.735802 10792 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":{}}} I1119 03:36:55.936199 10792 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" I1119 03:36:55.936256 10792 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1 I1119 03:36:56.239009 10792 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={} [32m•[0mI1119 03:36:56.789612 10792 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" E1119 03:36:58.888866 10792 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="timed out waiting for the condition" "cluster"="cluster-cache-test-h8mzr/test-cluster" [32m•[0mE1119 03:36:59.343440 10792 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="the server could not find the requested resource" "cluster"="cluster-cache-test-wjtxw/test-cluster" [32m•[0mE1119 03:36:59.881288 10792 cluster_cache.go:366] "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:46733/?timeout=50ms: dial tcp 127.0.0.1:46733: connect: connection refused" "cluster"="cluster-cache-test-4945x/test-cluster" [32m•[0mI1119 03:37:00.103351 10792 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}}} I1119 03:37:00.203721 10792 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" I1119 03:37:00.203780 10792 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1 [32m•[0mI1119 03:37:00.396024 10792 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" I1119 03:37:00.396162 10792 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E1119 03:37:00.438197 10792 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:33865/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=143&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:33865: connect: connection refused [1m[32mRan 5 of 5 Specs in 15.566 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestGinkgoSuite (15.57s) PASS ok sigs.k8s.io/cluster-api/controllers/remote 15.734s ? sigs.k8s.io/cluster-api/controllers/remote/fake [no test files] ? sigs.k8s.io/cluster-api/controlplane/kubeadm [no test files] === RUN TestKubeadmControlPlaneDefault ... skipping 201 lines ... I1119 03:37:09.707856 11628 server.go:199] controller-runtime/webhook "msg"="serving webhook server" "host"="" "port"=39367 I1119 03:37:09.708002 11628 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" --- PASS: TestClusterToKubeadmControlPlaneNoControlPlane (0.00s) === RUN TestClusterToKubeadmControlPlaneOtherControlPlane --- PASS: TestClusterToKubeadmControlPlaneOtherControlPlane (0.00s) === RUN TestReconcileUpdateObservedGeneration --- FAIL: TestReconcileUpdateObservedGeneration (10.92s) controller_test.go:230: Timed out after 10.000s. Expected <int64>: 2 to equal <int64>: 1 === RUN TestReconcileNoClusterOwnerRef I1119 03:37:20.633207 11628 controller.go:130] "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" --- PASS: TestReconcileNoClusterOwnerRef (0.00s) === RUN TestReconcileNoKCP --- PASS: TestReconcileNoKCP (0.00s) === RUN TestReconcileNoCluster E1119 03:37:20.634612 11628 controller.go:126] "msg"="Failed to retrieve owner Cluster from the API Server" "error"="clusters.cluster.x-k8s.io \"foo\" not found" "kubeadmControlPlane"="foo" "namespace"="test" --- PASS: TestReconcileNoCluster (0.00s) === RUN TestReconcilePaused I1119 03:37:20.635334 11628 controller.go:136] "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" I1119 03:37:20.635530 11628 controller.go:136] "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" --- PASS: TestReconcilePaused (0.00s) === RUN TestReconcileClusterNoEndpoints ... skipping 192 lines ... --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s) === RUN TestPreflightChecks === RUN TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass === RUN TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue I1119 03:37:35.233229 11628 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 I1119 03:37:35.233448 11628 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: [1m1668829016[0m Will run [1m1[0m of [1m1[0m specs E1119 03:37:35.261673 11628 controller.go:126] "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-mebq01\" not found" "kubeadmControlPlane"="kcp-foo-mebq01" "namespace"="test" [32m•[0m [1m[32mRan 1 of 1 Specs in 0.024 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (0.02s) === RUN TestKubeadmControlPlaneReconciler_upgradeControlPlane I1119 03:37:35.263450 11628 controller.go:246] "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-zhu7mu" "kubeadmControlPlane"="kcp-foo-zhu7mu" "namespace"="test" I1119 03:37:36.025439 11628 controller.go:331] "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-zhu7mu" "kubeadmControlPlane"="kcp-foo-zhu7mu" "namespace"="test" "needRollout"=["kcp-foo-zhu7mu-9jn94"] I1119 03:37:36.025630 11628 scale.go:212] "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-zhu7mu" "kubeadmControlPlane"="kcp-foo-zhu7mu" "namespace"="test" "failures"="[machine kcp-foo-zhu7mu-2mvbn does not have APIServerPodHealthy condition, machine kcp-foo-zhu7mu-2mvbn does not have ControllerManagerPodHealthy condition, machine kcp-foo-zhu7mu-2mvbn does not have SchedulerPodHealthy condition, machine kcp-foo-zhu7mu-2mvbn does not have EtcdPodHealthy condition, machine kcp-foo-zhu7mu-2mvbn does not have EtcdMemberHealthy condition]" --- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (0.76s) FAIL I1119 03:37:36.026775 11628 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" FAIL sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers 39.649s I1119 03:37:06.607317 11562 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook" "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster" I1119 03:37:06.607446 11562 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster" I1119 03:37:06.607475 11562 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook" "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster" I1119 03:37:06.607491 11562 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster" I1119 03:37:06.607563 11562 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook" "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine" I1119 03:37:06.607580 11562 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine" ... skipping 51 lines ... ================================== Random Seed: [1m1668829014[0m Will run [1m7[0m of [1m7[0m specs [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m [1m[32mRan 7 of 7 Specs in 0.002 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m7 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestControlPlane (0.00s) === RUN TestHasUnhealthyMachine --- PASS: TestHasUnhealthyMachine (0.00s) === RUN TestNewFailureDomainPicker === RUN TestNewFailureDomainPicker/simple === RUN TestNewFailureDomainPicker/no_machines ... skipping 111 lines ... ======================================= Random Seed: [1m1668829014[0m Will run [1m7[0m of [1m7[0m specs [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m [1m[32mRan 7 of 7 Specs in 0.000 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m7 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestMachineCollection (0.00s) === RUN TestUpdateEtcdConditions === RUN TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown === RUN TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines === RUN TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines === RUN TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition ... skipping 297 lines ... --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s) --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s) === RUN TestRemoveMachineFromKubeadmConfigMap === RUN TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil === RUN TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil === RUN TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0 E1119 03:37:08.081239 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:37:16.404338 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:37:25.390436 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:37:36.520712 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:37:52.993972 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:38:06.002608 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:38:23.650050 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:38:44.573427 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:39:15.589941 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" E1119 03:40:00.747129 11562 workload_cluster.go:354] "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found" === RUN TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0 === RUN TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0 === RUN TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0 --- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s) --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s) --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s) ... skipping 83 lines ... --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_<_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s) --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s) PASS E1119 03:40:00.754972 11562 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:40:00.755009 11562 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-882604675/tls.crt: no such file or directory" I1119 03:40:00.755039 11562 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" ok sigs.k8s.io/cluster-api/controlplane/kubeadm/internal 186.048s === RUN TestEtcdMembers_WithErrors --- PASS: TestEtcdMembers_WithErrors (0.00s) === RUN TestEtcdMembers_WithSuccess --- PASS: TestEtcdMembers_WithSuccess (0.00s) ... skipping 288 lines ... I1119 03:37:17.139368 11914 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1 I1119 03:37:17.139735 11914 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}} I1119 03:37:17.240147 11914 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}} I1119 03:37:17.340694 11914 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" I1119 03:37:17.340767 11914 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1 I1119 03:37:17.484174 11914 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-l7r9mv"} E1119 03:37:17.517579 11914 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mI1119 03:37:18.579097 11914 clusterresourcesetbinding_controller.go:84] "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-3gqjnt"} E1119 03:37:18.617893 11914 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mE1119 03:37:19.684386 11914 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" E1119 03:37:20.704510 11914 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mE1119 03:37:21.828624 11914 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" E1119 03:37:22.852806 11914 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" [32m•[0mE1119 03:37:23.873051 11914 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default" [32m•[0mI1119 03:37:23.878255 11914 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" I1119 03:37:23.878255 11914 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" I1119 03:37:23.878302 11914 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" [1m[32mRan 5 of 5 Specs in 19.941 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (19.94s) PASS ok sigs.k8s.io/cluster-api/exp/addons/controllers 19.989s ? sigs.k8s.io/cluster-api/exp/addons/controllers/predicates [no test files] === RUN TestMachinePoolDefault === RUN TestMachinePoolDefault/for_MachinePool ... skipping 61 lines ... --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s) --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s) --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s) === RUN TestReconcileMachinePoolInfrastructure === RUN TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready === RUN TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed E1119 03:37:08.357682 12089 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.01s) --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s) --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s) === RUN TestMachinePoolFinalizer ... skipping 92 lines ... [32m•[0mI1119 03:37:19.708428 12089 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI1119 03:37:19.742120 12089 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI1119 03:37:19.744501 12089 machinepool_controller_phases.go:268] "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" [32m•[0mI1119 03:37:19.778449 12089 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinepool" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}} I1119 03:37:19.783817 12089 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI1119 03:37:19.813697 12089 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0m[32m•[0mE1119 03:37:19.816454 12089 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:37:19.816520 12089 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-943307176/tls.crt: no such file or directory" E1119 03:37:19.816545 12089 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:37:19.816564 12089 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-943307176/tls.crt: no such file or directory" I1119 03:37:19.816686 12089 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 9 of 9 Specs in 11.452 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m9 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestAPIs (11.45s) PASS ok sigs.k8s.io/cluster-api/exp/controllers 11.693s ? sigs.k8s.io/cluster-api/exp/util [no test files] ? sigs.k8s.io/cluster-api/feature [no test files] ? sigs.k8s.io/cluster-api/hack/boilerplate/test [no test files] ... skipping 266 lines ... --- PASS: TestGetFirstReasonAndMessage (0.00s) === RUN TestNewConditionsGroup --- PASS: TestNewConditionsGroup (0.00s) === RUN TestMergeRespectPriority === RUN TestMergeRespectPriority/aggregate_nil_list_return_nil === RUN TestMergeRespectPriority/aggregate_empty_list_return_nil === RUN TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error === RUN TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning === RUN TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info === RUN TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info === RUN TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown === RUN TestMergeRespectPriority/nil_conditions_are_ignored --- PASS: TestMergeRespectPriority (0.00s) --- PASS: TestMergeRespectPriority/aggregate_nil_list_return_nil (0.00s) --- PASS: TestMergeRespectPriority/aggregate_empty_list_return_nil (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info (0.00s) --- PASS: TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown (0.00s) --- PASS: TestMergeRespectPriority/nil_conditions_are_ignored (0.00s) === RUN TestNewPatch === RUN TestNewPatch/No_changes_return_empty_patch ... skipping 201 lines ... I1119 03:37:45.270360 15130 server.go:121] controller-runtime/webhook "msg"="registering webhook" "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset" I1119 03:37:45.270565 15130 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server" I1119 03:37:45.271436 15130 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate" I1119 03:37:45.271636 15130 server.go:199] controller-runtime/webhook "msg"="serving webhook server" "host"="" "port"=42681 I1119 03:37:45.271711 15130 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher" [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0mI1119 03:37:46.224519 15130 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" E1119 03:37:46.224520 15130 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory" E1119 03:37:46.224584 15130 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-938994718/tls.crt: no such file or directory" [1m[32mRan 14 of 14 Specs in 7.217 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m14 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestPatch (7.22s) === RUN TestToUnstructured === RUN TestToUnstructured/with_a_typed_object === RUN TestToUnstructured/with_an_unstructured_object --- PASS: TestToUnstructured (0.00s) --- PASS: TestToUnstructured/with_a_typed_object (0.00s) ... skipping 105 lines ... --- PASS: TestToUnstructured/returns_error_for_invalid_yaml#01 (0.00s) --- PASS: TestToUnstructured/returns_error_for_invalid_yaml#02 (0.00s) === RUN TestFromUnstructured --- PASS: TestFromUnstructured (0.00s) PASS ok sigs.k8s.io/cluster-api/util/yaml 0.035s FAIL make: *** [Makefile:116: test] Error 1