Bug 1804635 - Machine controller incorrectly printed waiting seconds during node drain
Summary: Machine controller incorrectly printed waiting seconds during node drain
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Cloud Compute
Version: 4.4
Hardware: Unspecified
OS: Unspecified
low
low
Target Milestone: ---
: 4.5.0
Assignee: Alexander Demicev
QA Contact: Milind Yadav
URL:
Whiteboard:
Depends On:
Blocks: 1810531
TreeView+ depends on / blocked
 
Reported: 2020-02-19 10:21 UTC by Jianwei Hou
Modified: 2020-08-04 18:01 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1810531 (view as bug list)
Environment:
Last Closed: 2020-08-04 18:01:08 UTC
Target Upstream Version:
Embargoed:
miyadav: needinfo+


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift machine-api-operator pull 495 0 None closed Bug 1804635: Fix timeout formatting 2021-02-08 06:49:26 UTC
Red Hat Product Errata RHBA-2020:2409 0 None None None 2020-08-04 18:01:13 UTC

Description Jianwei Hou 2020-02-19 10:21:27 UTC
Description of problem:
Delete a machine, in machine controller log one line printed as:
```
I0219 10:10:31.033535       1 controller.go:361] "qe-jhou-rqfpj-worker-centralus2-tqdvz": Node "qe-jhou-rqfpj-worker-centralus2-tqdvz" is unreachable, draining will wait 'Ĭ' seconds after pod is signalled for deletion and skip after it
```

Version-Release number of selected component (if applicable):
4.4.0-0.nightly-2020-02-18-211831(IPI Azure)

How reproducible:
Always

Steps to Reproduce:
1. Delete a machine
2. oc -n openshift-machine-api logs machine-api-controllers-75cbb7f444-rkqpl -c machine-controller -f

Actual results:
Got log: "draining will wait 'Ĭ' seconds after"

Expected results:
The waiting second printed correctly

Additional info:

Comment 3 Milind Yadav 2020-03-12 09:03:16 UTC
Description of problem:
Delete a machine, in machine controller log one line printed as:
```
I0219 10:10:31.033535       1 controller.go:361] "qe-jhou-rqfpj-worker-centralus2-tqdvz": Node "qe-jhou-rqfpj-worker-centralus2-tqdvz" is unreachable, draining will wait 'Ĭ' seconds after pod is signalled for deletion and skip after it
```

NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.5.0-0.nightly-2020-03-12-041748   True        False         89m     Cluster version is 4.5.0-0.nightly-2020-03-12-041748


How reproducible:
Always

Steps to Reproduce:
1. Delete a machine
2. oc -n openshift-machine-api logs machine-api-controllers-75cbb7f444-rkqpl -c machine-controller -f

Actual results:
Got log: "I0312 08:57:12.120631       1 controller.go:361] "zhsun9-l4nxj-worker-westus-snk6x": Node "zhsun9-l4nxj-worker-westus-snk6x" is unreachable, draining will wait 'Ĭ' seconds after pod is signalled for deletion and skip after it
I0312 08:57:33.327193       1 controller.go:361] "zhsun9-l4nxj-worker-westus-snk6x": Node "zhsun9-l4nxj-worker-westus-snk6x" is unreachable, draining will wait 'Ĭ' seconds after pod is signalled for deletion and skip after it


Expected results:
The waiting second printed correctly

Additional info:

Comment 7 Milind Yadav 2020-04-24 09:49:10 UTC
Validated on :
[miyadav@miyadav ManualRun]$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.5.0-0.nightly-2020-04-21-103613   True        False         25m     Cluster version is 4.5.0-0.nightly-2020-04-21-103613

Reproducible Always.


Steps to Reproduce:
1. Delete a machine
2. oc logs -f  machine-api-controllers-788f58b4-jl9bj -c machine-controller 

Actual results:
Got log: 
I0424 08:34:37.941409       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-mwnhx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-mwnhx","uid":"dee5926c-4624-4538-96a8-f5a7166e6d9a","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"39778"} "reason"="Updated"
I0424 08:35:19.553512       1 controller.go:163] miyadav-jpfdm-worker-westus-kbdsp: reconciling Machine
I0424 08:35:19.553550       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-kbdsp exists
I0424 08:35:19.595738       1 controller.go:73] controllers/MachineSet "msg"="Reconciling" "machineset"="miyadav-jpfdm-worker-westus" "namespace"="openshift-machine-api" 
I0424 08:35:19.630581       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machineset" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus"}
I0424 08:35:24.931161       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-kbdsp
I0424 08:35:24.931189       1 controller.go:419] miyadav-jpfdm-worker-westus-kbdsp: going into phase "Failed"
I0424 08:35:24.945906       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-kbdsp"}
I0424 08:35:24.946009       1 controller.go:163] miyadav-jpfdm-worker-westus-kbdsp: reconciling Machine
W0424 08:35:24.946028       1 controller.go:260] miyadav-jpfdm-worker-westus-kbdsp: machine has gone "Failed" phase. It won't reconcile
I0424 08:35:24.946058       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-kbdsp"}.
.
.
.


Expected results:
The waiting second printed correctly

Additional info:
The deleted machine went to failed status : oc get machines
.
.
miyadav-jpfdm-worker-westus-kbdsp   Failed    Standard_D2s_v3   westus          97m
.
.
Although the machine status is shown as failed in openshift GUI and from command line tool (oc) , the machine is successfully deleted from Azure (showing as deleted in Azure GUI).
[could be related to - https://bugzilla.redhat.com/show_bug.cgi?id=1827589 ]

The drain seems to have happened successfully and I didn't hit  the path for log --
.
.
"I0312 08:57:33.327193       1 controller.go:361] "zhsun9-l4nxj-worker-westus-snk6x": Node "zhsun9-l4nxj-worker-westus-snk6x" is unreachable, draining will wait 'Ĭ' seconds after pod is signalled for deletion and skip after it"
.
.

Have tried multiple times but couldn't reproduce.

Hence not Verifying it. Please have a look and provide more info , if it needs some PR to be merged before testing again.

Comment 8 Alberto 2020-04-24 10:04:06 UTC
would you please try again deleting an existing machine and share full machine controller logs?

Comment 9 Milind Yadav 2020-04-24 10:37:35 UTC
Here are full logs : will ping you env details over slack , just in case you want to check in the env too .

I0424 08:52:12.954213       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:52:12.954242       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:52:12.954249       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:52:13.730807       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:52:13.804777       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:52:13.804836       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:52:13.804842       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:52:13.820723       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:52:13.820753       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:52:13.820767       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:52:13.820847       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:52:31.473043       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:52:31.473071       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:52:31.926008       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:52:31.926036       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:52:31.926041       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:52:32.865821       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:52:32.914256       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:52:32.914409       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:52:32.914415       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:52:32.933299       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:52:32.933322       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:52:32.933333       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:52:32.933388       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:52:52.933656       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:52:52.933685       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:52:53.345006       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:52:53.345033       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:52:53.345040       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:52:54.226071       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:52:54.342997       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:52:54.343035       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:52:54.343041       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:52:54.366607       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:52:54.366636       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:52:54.366647       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:52:54.366738       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:53:14.366886       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:53:14.366929       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:53:14.885426       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:53:14.885452       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:53:14.885458       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:53:15.969306       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:53:16.035953       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:53:16.035989       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:53:16.036064       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:53:16.052157       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:53:16.052180       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:53:16.052195       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:53:16.052230       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:53:36.052387       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:53:36.052416       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:53:36.362199       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:53:36.362321       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:53:36.362356       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:53:37.479560       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:53:37.601444       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:53:37.601475       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:53:37.601480       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:53:37.621801       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:53:37.621823       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:53:37.621833       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:53:37.621889       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:53:57.622049       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:53:57.622077       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:53:58.087865       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:53:58.087897       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:53:58.087905       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:53:58.977509       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:53:59.137127       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:53:59.137172       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:53:59.137182       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:53:59.153078       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:53:59.153099       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:53:59.153107       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:53:59.153148       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:54:19.153310       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:54:19.153338       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:54:19.500604       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:19.500632       1 controller.go:307] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent create
I0424 08:54:19.500638       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:20.309399       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-jx8zx-nic
I0424 08:54:20.358323       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:54:20.358356       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:54:20.358400       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:54:20.374860       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-jx8zx"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile
W0424 08:54:20.374884       1 controller.go:309] miyadav-jpfdm-worker-westus-jx8zx: failed to create machine: requeue in: 20s
I0424 08:54:20.374898       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 08:54:20.374946       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-jx8zx\"s: failed to create vm miyadav-jpfdm-worker-westus-jx8zx : vm miyadav-jpfdm-worker-westus-jx8zx is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="FailedCreate"
I0424 08:54:40.375224       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:54:40.375251       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:54:40.835030       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:40.835052       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:54:40.835062       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:54:40.835067       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:41.275456       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
E0424 08:54:41.300403       1 controller.go:278] miyadav-jpfdm-worker-westus-jx8zx: instance exists but providerID or addresses has not been given to the machine yet, requeuing
I0424 08:54:41.300454       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:54:41.300461       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:54:41.300529       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"46687"} "reason"="Updated"
I0424 08:54:42.059825       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:42.059849       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:54:42.059859       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:54:42.059864       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:42.575814       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:54:42.575871       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:54:42.575879       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:54:42.591337       1 controller.go:419] miyadav-jpfdm-worker-westus-jx8zx: going into phase "Provisioned"
I0424 08:54:42.591470       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47498"} "reason"="Updated"
I0424 08:54:42.607410       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:54:42.607465       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:54:42.607472       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:54:43.015400       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:43.015422       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:54:43.015432       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:54:43.015437       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:54:43.455031       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:54:43.455089       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:54:43.455095       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:54:43.472325       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:54:43.472415       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:55:11.300668       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:55:11.300696       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:55:11.673574       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:55:11.673603       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:55:11.673613       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:55:11.673618       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:55:12.197648       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:55:12.197687       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:55:12.197692       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:55:12.215575       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:55:12.215667       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:55:42.215832       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:55:42.215863       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:55:42.685353       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:55:42.685375       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:55:42.685384       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:55:42.685389       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:55:43.022329       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:55:43.022366       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:55:43.022370       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:55:43.039812       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:55:43.039894       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:56:13.040023       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:56:13.040050       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:56:13.494568       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:56:13.494593       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:56:13.494604       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:56:13.494611       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:56:14.097531       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:56:14.097734       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:56:14.097754       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:56:14.114498       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:56:14.114579       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:56:44.114765       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:56:44.114802       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:56:44.574994       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:56:44.575020       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:56:44.575032       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:56:44.575039       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:56:45.020435       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:56:45.020472       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:56:45.020477       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:56:45.037271       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:56:45.037359       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:57:15.037510       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:57:15.037541       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:57:15.444562       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:57:15.444587       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:57:15.444599       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:57:15.444606       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:57:15.963340       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:57:15.963389       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:57:15.963396       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:57:15.978996       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:57:15.979081       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:57:45.979245       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:57:45.979275       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:57:46.364522       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:57:46.364544       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:57:46.364553       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:57:46.364558       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:57:46.933466       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:57:46.933513       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:57:46.933519       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:57:46.950162       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:57:46.950234       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:58:16.950441       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:58:16.950472       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:58:17.390535       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:17.390557       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:58:17.390567       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:58:17.390571       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:17.823740       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:17.823776       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:17.823781       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:58:17.846189       1 controller.go:287] miyadav-jpfdm-worker-westus-jx8zx: has no node yet, requeuing
I0424 08:58:17.846257       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"47506"} "reason"="Updated"
I0424 08:58:44.161642       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:58:44.161668       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:58:44.532309       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:44.532336       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:58:44.532346       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:58:44.532351       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:45.030307       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:45.030345       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:45.030350       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:58:45.051005       1 controller.go:419] miyadav-jpfdm-worker-westus-jx8zx: going into phase "Running"
I0424 08:58:45.051144       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"48879"} "reason"="Updated"
I0424 08:58:45.065301       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-jx8zx"}
I0424 08:58:45.065441       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:58:45.065458       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:58:45.294115       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:45.294138       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:58:45.294149       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:58:45.294154       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:45.783554       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:45.783596       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:45.783603       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:58:45.800047       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-jx8zx"}
I0424 08:58:45.800108       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"48935"} "reason"="Updated"
I0424 08:58:47.846422       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 08:58:47.846449       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 08:58:48.156172       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:48.156227       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 08:58:48.156237       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 08:58:48.156242       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 08:58:48.538555       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:48.538601       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 08:58:48.538610       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 08:58:48.559247       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-jx8zx"}
I0424 08:58:48.559312       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"48935"} "reason"="Updated"
I0424 09:00:15.066449       1 controller.go:163] miyadav-jpfdm-worker-westus-jx8zx: reconciling Machine
I0424 09:00:15.066479       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-jx8zx exists
I0424 09:00:15.080370       1 controller.go:73] controllers/MachineSet "msg"="Reconciling" "machineset"="miyadav-jpfdm-worker-westus" "namespace"="openshift-machine-api" 
I0424 09:00:15.095820       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machineset" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus"}
I0424 09:00:15.499274       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-jx8zx
I0424 09:00:15.499297       1 reconciler.go:372] Machine e7a41736-34c9-4b3b-b511-49db50281abc is running
I0424 09:00:15.499310       1 controller.go:271] miyadav-jpfdm-worker-westus-jx8zx: reconciling machine triggers idempotent update
I0424 09:00:15.499317       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-jx8zx
I0424 09:00:16.004793       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 09:00:16.004842       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-jx8zx: status unchanged
I0424 09:00:16.004848       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-jx8zx: patching machine
I0424 09:00:16.025551       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-jx8zx"}
I0424 09:00:16.025624       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-jx8zx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-jx8zx","uid":"9d3049f3-57f5-4c3c-950f-79bc27a5dbd8","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"49538"} "reason"="Updated"
I0424 10:31:33.877580       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:31:33.877613       1 controller.go:419] miyadav-jpfdm-worker-westus-mwnhx: going into phase "Deleting"
I0424 10:31:33.890053       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:31:33.927587       1 controller.go:73] controllers/MachineSet "msg"="Reconciling" "machineset"="miyadav-jpfdm-worker-westus" "namespace"="openshift-machine-api" 
I0424 10:31:33.937011       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machineset" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus"}
I0424 10:31:33.948901       1 controller.go:73] controllers/MachineSet "msg"="Reconciling" "machineset"="miyadav-jpfdm-worker-westus" "namespace"="openshift-machine-api" 
I0424 10:31:33.956657       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machineset" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus"}
I0424 10:31:34.012411       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
I0424 10:31:34.012422       1 controller.go:468] evicting pod openshift-cluster-storage-operator/csi-snapshot-controller-operator-84547858b5-66q96
I0424 10:31:34.012455       1 controller.go:468] evicting pod openshift-cluster-storage-operator/csi-snapshot-controller-7b8f76846d-5sdvf
I0424 10:31:34.012471       1 controller.go:468] evicting pod openshift-image-registry/image-registry-5b6cc796bc-t4rb5
I0424 10:31:34.012482       1 controller.go:468] evicting pod openshift-monitoring/openshift-state-metrics-786cbff76-4ml46
I0424 10:31:34.012515       1 controller.go:468] evicting pod openshift-monitoring/alertmanager-main-0
I0424 10:31:34.012556       1 controller.go:468] evicting pod openshift-kube-storage-version-migrator/migrator-6dbc9bc7bc-j5mmv
I0424 10:31:34.012613       1 controller.go:468] evicting pod openshift-monitoring/prometheus-adapter-64f6c8f478-6pfcx
I0424 10:31:34.012627       1 controller.go:468] evicting pod openshift-monitoring/telemeter-client-7bfb5d6cb-687d8
I0424 10:31:34.012564       1 controller.go:468] evicting pod openshift-monitoring/prometheus-k8s-1
I0424 10:31:34.012587       1 controller.go:468] evicting pod openshift-monitoring/grafana-cb59bb8d5-lr8n8
I0424 10:31:34.012742       1 controller.go:468] evicting pod openshift-monitoring/prometheus-adapter-64f6c8f478-vw9rg
I0424 10:31:34.012905       1 controller.go:468] evicting pod openshift-monitoring/thanos-querier-56485688f8-q4vjw
I0424 10:31:44.093625       1 controller.go:352] Evicted pod from Nodepodcsi-snapshot-controller-operator-84547858b5-66q96/openshift-cluster-storage-operator
I0424 10:31:44.094298       1 controller.go:352] Evicted pod from Nodepodtelemeter-client-7bfb5d6cb-687d8/openshift-monitoring
I0424 10:31:44.241626       1 controller.go:352] Evicted pod from Nodepodopenshift-state-metrics-786cbff76-4ml46/openshift-monitoring
I0424 10:31:44.284008       1 controller.go:352] Evicted pod from Nodepodprometheus-k8s-1/openshift-monitoring
I0424 10:31:44.320494       1 controller.go:352] Evicted pod from Nodepodimage-registry-5b6cc796bc-t4rb5/openshift-image-registry
I0424 10:31:44.429503       1 controller.go:352] Evicted pod from Nodepodthanos-querier-56485688f8-q4vjw/openshift-monitoring
I0424 10:31:45.081413       1 controller.go:352] Evicted pod from Nodepodcsi-snapshot-controller-7b8f76846d-5sdvf/openshift-cluster-storage-operator
I0424 10:31:45.092110       1 controller.go:352] Evicted pod from Nodepodprometheus-adapter-64f6c8f478-vw9rg/openshift-monitoring
I0424 10:31:45.123305       1 controller.go:352] Evicted pod from Nodepodgrafana-cb59bb8d5-lr8n8/openshift-monitoring
I0424 10:31:45.123590       1 controller.go:352] Evicted pod from Nodepodprometheus-adapter-64f6c8f478-6pfcx/openshift-monitoring
I0424 10:31:45.134398       1 controller.go:352] Evicted pod from Nodepodmigrator-6dbc9bc7bc-j5mmv/openshift-kube-storage-version-migrator
I0424 10:31:45.158844       1 controller.go:352] Evicted pod from Nodepodalertmanager-main-0/openshift-monitoring
W0424 10:31:54.359871       1 controller.go:374] drain failed for machine "miyadav-jpfdm-worker-westus-mwnhx": error when waiting for pod "router-default-68dbf78447-hvgsq" terminating: global timeout reached: 20s
E0424 10:31:54.359927       1 controller.go:211] miyadav-jpfdm-worker-westus-mwnhx: failed to drain node for machine: requeue in: 20s
I0424 10:31:54.359947       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:31:54.360010       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:31:54.374565       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-rdl6b"}
I0424 10:31:54.374616       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:31:54.374628       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:31:54.469982       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
E0424 10:31:54.486455       1 controller.go:468] error when evicting pod "router-default-68dbf78447-hvgsq" (will retry after 5s): Cannot evict pod as it would violate the pod's disruption budget.
I0424 10:31:59.486712       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
E0424 10:31:59.497794       1 controller.go:468] error when evicting pod "router-default-68dbf78447-hvgsq" (will retry after 5s): Cannot evict pod as it would violate the pod's disruption budget.
I0424 10:32:04.497961       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
E0424 10:32:04.509819       1 controller.go:468] error when evicting pod "router-default-68dbf78447-hvgsq" (will retry after 5s): Cannot evict pod as it would violate the pod's disruption budget.
I0424 10:32:09.510017       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
E0424 10:32:09.519566       1 controller.go:468] error when evicting pod "router-default-68dbf78447-hvgsq" (will retry after 5s): Cannot evict pod as it would violate the pod's disruption budget.
I0424 10:32:14.519744       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
W0424 10:32:14.519899       1 controller.go:374] drain failed for machine "miyadav-jpfdm-worker-westus-mwnhx": error when evicting pod "router-default-68dbf78447-hvgsq": global timeout reached: 20s
E0424 10:32:14.520001       1 controller.go:211] miyadav-jpfdm-worker-westus-mwnhx: failed to drain node for machine: requeue in: 20s
I0424 10:32:14.520017       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:32:14.520102       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:32:14.520119       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:32:15.119257       1 controller.go:419] miyadav-jpfdm-worker-westus-rdl6b: going into phase "Provisioning"
I0424 10:32:15.134605       1 controller.go:307] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent create
I0424 10:32:15.134640       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:32:16.376032       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:32:16.429171       1 virtualmachines.go:73] getting nic miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:32:16.581199       1 virtualmachines.go:82] got nic miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:32:16.581221       1 virtualmachines.go:84] creating vm miyadav-jpfdm-worker-westus-rdl6b 
I0424 10:32:17.993519       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
E0424 10:32:18.015087       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-rdl6b"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : failed to create or get machine: compute.VirtualMachinesCreateOrUpdateFuture: asynchronous operation has not completed
W0424 10:32:18.015112       1 controller.go:309] miyadav-jpfdm-worker-westus-rdl6b: failed to create machine: requeue in: 20s
I0424 10:32:18.015122       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:32:18.015169       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:32:18.015185       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:32:18.016235       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-rdl6b\"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : failed to create or get machine: compute.VirtualMachinesCreateOrUpdateFuture: asynchronous operation has not completed" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-rdl6b","uid":"ca5bf2e4-758f-486a-98d9-42de7920c493","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"81497"} "reason"="FailedCreate"
I0424 10:32:18.107702       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
W0424 10:32:38.143233       1 controller.go:374] drain failed for machine "miyadav-jpfdm-worker-westus-mwnhx": error when waiting for pod "router-default-68dbf78447-hvgsq" terminating: global timeout reached: 20s
E0424 10:32:38.143278       1 controller.go:211] miyadav-jpfdm-worker-westus-mwnhx: failed to drain node for machine: requeue in: 20s
I0424 10:32:38.143292       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:32:38.143362       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:32:38.143371       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:32:38.657359       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:32:38.657394       1 controller.go:307] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent create
I0424 10:32:38.657401       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:32:39.786684       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:32:39.926187       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
E0424 10:32:39.951608       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-rdl6b"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile
W0424 10:32:39.951712       1 controller.go:309] miyadav-jpfdm-worker-westus-rdl6b: failed to create machine: requeue in: 20s
I0424 10:32:39.951732       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:32:39.951790       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:32:39.951811       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:32:39.952117       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-rdl6b\"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-rdl6b","uid":"ca5bf2e4-758f-486a-98d9-42de7920c493","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"81531"} "reason"="FailedCreate"
I0424 10:32:40.040236       1 controller.go:468] evicting pod openshift-ingress/router-default-68dbf78447-hvgsq
I0424 10:32:53.083530       1 controller.go:352] Evicted pod from Nodepodrouter-default-68dbf78447-hvgsq/openshift-ingress
I0424 10:32:53.083583       1 controller.go:378] drain successful for machine "miyadav-jpfdm-worker-westus-mwnhx"
I0424 10:32:53.083623       1 actuator.go:128] Deleting machine miyadav-jpfdm-worker-westus-mwnhx
I0424 10:32:53.083761       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Node \"miyadav-jpfdm-worker-westus-mwnhx\" drained" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-mwnhx","uid":"dee5926c-4624-4538-96a8-f5a7166e6d9a","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"80722"} "reason"="Deleted"
I0424 10:32:53.084696       1 virtualmachines.go:225] deleting vm miyadav-jpfdm-worker-westus-mwnhx 
I0424 10:32:53.685198       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-mwnhx: patching machine
E0424 10:32:53.710330       1 actuator.go:79] Machine error: failed to delete machine "miyadav-jpfdm-worker-westus-mwnhx": failed to delete machine: compute.VirtualMachinesDeleteFuture: asynchronous operation has not completed
E0424 10:32:53.710360       1 controller.go:224] miyadav-jpfdm-worker-westus-mwnhx: failed to delete machine: requeue in: 20s
I0424 10:32:53.710370       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:32:53.710416       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:32:53.710425       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:32:53.710461       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="DeleteError: failed to delete machine \"miyadav-jpfdm-worker-westus-mwnhx\": failed to delete machine: compute.VirtualMachinesDeleteFuture: asynchronous operation has not completed" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-mwnhx","uid":"dee5926c-4624-4538-96a8-f5a7166e6d9a","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"80722"} "reason"="FailedDelete"
I0424 10:33:04.816830       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:33:04.816858       1 controller.go:307] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent create
I0424 10:33:04.816864       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:33:21.122726       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:33:31.331566       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:33:31.331610       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:33:31.331616       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
E0424 10:33:31.348547       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-rdl6b"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile
W0424 10:33:31.348567       1 controller.go:309] miyadav-jpfdm-worker-westus-rdl6b: failed to create machine: requeue in: 20s
I0424 10:33:31.348578       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:33:31.348622       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:33:31.348633       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:33:31.348689       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-rdl6b\"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-rdl6b","uid":"ca5bf2e4-758f-486a-98d9-42de7920c493","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"81693"} "reason"="FailedCreate"
I0424 10:33:31.355191       1 controller.go:332] Could not find node from noderef, it may have already been deleted: miyadav-jpfdm-worker-westus-mwnhx
I0424 10:33:31.355208       1 actuator.go:128] Deleting machine miyadav-jpfdm-worker-westus-mwnhx
I0424 10:33:31.355724       1 virtualmachines.go:225] deleting vm miyadav-jpfdm-worker-westus-mwnhx 
I0424 10:33:31.875979       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-mwnhx: status unchanged
I0424 10:33:31.876015       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-mwnhx: status unchanged
I0424 10:33:31.876020       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-mwnhx: patching machine
E0424 10:33:31.893325       1 actuator.go:79] Machine error: failed to delete machine "miyadav-jpfdm-worker-westus-mwnhx": failed to delete machine: compute.VirtualMachinesDeleteFuture: asynchronous operation has not completed
E0424 10:33:31.893360       1 controller.go:224] miyadav-jpfdm-worker-westus-mwnhx: failed to delete machine: requeue in: 20s
I0424 10:33:31.893367       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:33:31.893412       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:33:31.893419       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:33:31.893452       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="DeleteError: failed to delete machine \"miyadav-jpfdm-worker-westus-mwnhx\": failed to delete machine: compute.VirtualMachinesDeleteFuture: asynchronous operation has not completed" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-mwnhx","uid":"dee5926c-4624-4538-96a8-f5a7166e6d9a","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"82010"} "reason"="FailedDelete"
I0424 10:33:32.536596       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:33:32.536625       1 controller.go:307] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent create
I0424 10:33:32.536631       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:33:33.521830       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:33:33.566354       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:33:33.566393       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:33:33.566400       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
E0424 10:33:33.582424       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-rdl6b"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile
W0424 10:33:33.582446       1 controller.go:309] miyadav-jpfdm-worker-westus-rdl6b: failed to create machine: requeue in: 20s
I0424 10:33:33.582457       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:33:33.582494       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-rdl6b\"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-rdl6b","uid":"ca5bf2e4-758f-486a-98d9-42de7920c493","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"81693"} "reason"="FailedCreate"
I0424 10:33:51.348785       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:33:51.348815       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:33:51.689788       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:33:51.689814       1 controller.go:307] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent create
I0424 10:33:51.689820       1 actuator.go:85] Creating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:33:52.879417       1 networkinterfaces.go:225] successfully created network interface miyadav-jpfdm-worker-westus-rdl6b-nic
I0424 10:33:52.923770       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:33:52.923801       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:33:52.923806       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
E0424 10:33:52.940931       1 actuator.go:79] Machine error: failed to reconcile machine "miyadav-jpfdm-worker-westus-rdl6b"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile
W0424 10:33:52.940955       1 controller.go:309] miyadav-jpfdm-worker-westus-rdl6b: failed to create machine: requeue in: 20s
I0424 10:33:52.940967       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:33:52.941008       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:33:52.941020       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:33:52.941051       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="CreateError: failed to reconcile machine \"miyadav-jpfdm-worker-westus-rdl6b\"s: failed to create vm miyadav-jpfdm-worker-westus-rdl6b : vm miyadav-jpfdm-worker-westus-rdl6b is still in provisioning state Creating, reconcile" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-rdl6b","uid":"ca5bf2e4-758f-486a-98d9-42de7920c493","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"81693"} "reason"="FailedCreate"
I0424 10:33:52.948611       1 controller.go:332] Could not find node from noderef, it may have already been deleted: miyadav-jpfdm-worker-westus-mwnhx
I0424 10:33:52.948633       1 actuator.go:128] Deleting machine miyadav-jpfdm-worker-westus-mwnhx
I0424 10:33:52.949219       1 virtualmachines.go:225] deleting vm miyadav-jpfdm-worker-westus-mwnhx 
I0424 10:33:53.287244       1 virtualmachines.go:242] successfully deleted vm miyadav-jpfdm-worker-westus-mwnhx 
I0424 10:33:53.287268       1 disks.go:49] deleting disk miyadav-jpfdm-worker-westus-mwnhx_OSDisk
I0424 10:33:53.611323       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-mwnhx: status unchanged
I0424 10:33:53.611440       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-mwnhx: status unchanged
I0424 10:33:53.611447       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-mwnhx: patching machine
E0424 10:33:53.628982       1 actuator.go:79] Machine error: failed to delete machine "miyadav-jpfdm-worker-westus-mwnhx": failed to delete OS disk: result error: compute.DisksDeleteFuture: asynchronous operation has not completed
E0424 10:33:53.629015       1 controller.go:224] miyadav-jpfdm-worker-westus-mwnhx: failed to delete machine: requeue in: 20s
I0424 10:33:53.629024       1 controller.go:400] Actuator returned requeue-after error: requeue in: 20s
I0424 10:33:53.629132       1 recorder.go:52] controller-runtime/manager/events "msg"="Warning"  "message"="DeleteError: failed to delete machine \"miyadav-jpfdm-worker-westus-mwnhx\": failed to delete OS disk: result error: compute.DisksDeleteFuture: asynchronous operation has not completed" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-mwnhx","uid":"dee5926c-4624-4538-96a8-f5a7166e6d9a","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"82010"} "reason"="FailedDelete"
I0424 10:34:12.941205       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:34:12.941234       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:34:13.349545       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:34:13.349573       1 reconciler.go:372] Machine 87eb5dbb-df82-40d7-81c8-4de92bc59cb7 is running
I0424 10:34:13.349584       1 controller.go:271] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent update
I0424 10:34:13.349590       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:34:13.938421       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
E0424 10:34:13.965066       1 controller.go:278] miyadav-jpfdm-worker-westus-rdl6b: instance exists but providerID or addresses has not been given to the machine yet, requeuing
I0424 10:34:13.965740       1 controller.go:163] miyadav-jpfdm-worker-westus-mwnhx: reconciling Machine
I0424 10:34:13.965851       1 controller.go:203] miyadav-jpfdm-worker-westus-mwnhx: reconciling machine triggers delete
I0424 10:34:13.965134       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Updated machine \"miyadav-jpfdm-worker-westus-rdl6b\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-rdl6b","uid":"ca5bf2e4-758f-486a-98d9-42de7920c493","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"81693"} "reason"="Updated"
I0424 10:34:13.976395       1 controller.go:332] Could not find node from noderef, it may have already been deleted: miyadav-jpfdm-worker-westus-mwnhx
I0424 10:34:13.976415       1 actuator.go:128] Deleting machine miyadav-jpfdm-worker-westus-mwnhx
I0424 10:34:13.977145       1 virtualmachines.go:225] deleting vm miyadav-jpfdm-worker-westus-mwnhx 
I0424 10:34:14.351822       1 virtualmachines.go:242] successfully deleted vm miyadav-jpfdm-worker-westus-mwnhx 
I0424 10:34:14.351845       1 disks.go:49] deleting disk miyadav-jpfdm-worker-westus-mwnhx_OSDisk
I0424 10:34:14.429128       1 disks.go:65] successfully deleted disk miyadav-jpfdm-worker-westus-mwnhx_OSDisk
I0424 10:34:14.429154       1 networkinterfaces.go:235] deleting nic miyadav-jpfdm-worker-westus-mwnhx-nic
I0424 10:34:14.852371       1 networkinterfaces.go:254] successfully deleted nic miyadav-jpfdm-worker-westus-mwnhx-nic
I0424 10:34:14.852438       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-mwnhx: status unchanged
I0424 10:34:14.852477       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-mwnhx: status unchanged
I0424 10:34:14.852483       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-mwnhx: patching machine
I0424 10:34:14.870521       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-mwnhx exists
I0424 10:34:14.870597       1 recorder.go:52] controller-runtime/manager/events "msg"="Normal"  "message"="Deleted machine \"miyadav-jpfdm-worker-westus-mwnhx\"" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-jpfdm-worker-westus-mwnhx","uid":"dee5926c-4624-4538-96a8-f5a7166e6d9a","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"82010"} "reason"="Deleted"
I0424 10:34:15.097406       1 controller.go:241] miyadav-jpfdm-worker-westus-mwnhx: deleting node "miyadav-jpfdm-worker-westus-mwnhx" for machine
I0424 10:34:15.097448       1 controller.go:388] Node "miyadav-jpfdm-worker-westus-mwnhx" not found
I0424 10:34:15.118347       1 controller.go:255] miyadav-jpfdm-worker-westus-mwnhx: machine deletion successful
I0424 10:34:15.118389       1 controller.go:282] controller-runtime/controller "msg"="Successfully Reconciled"  "controller"="machine_controller" "request"={"Namespace":"openshift-machine-api","Name":"miyadav-jpfdm-worker-westus-mwnhx"}
I0424 10:34:15.118427       1 controller.go:163] miyadav-jpfdm-worker-westus-rdl6b: reconciling Machine
I0424 10:34:15.118436       1 actuator.go:196] Checking if machine miyadav-jpfdm-worker-westus-rdl6b exists
I0424 10:34:15.429508       1 reconciler.go:352] Found vm for machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:34:15.429532       1 reconciler.go:372] Machine 87eb5dbb-df82-40d7-81c8-4de92bc59cb7 is running
I0424 10:34:15.429543       1 controller.go:271] miyadav-jpfdm-worker-westus-rdl6b: reconciling machine triggers idempotent update
I0424 10:34:15.429549       1 actuator.go:163] Updating machine miyadav-jpfdm-worker-westus-rdl6b
I0424 10:34:15.802096       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:34:15.802135       1 machine_scope.go:169] miyadav-jpfdm-worker-westus-rdl6b: status unchanged
I0424 10:34:15.802140       1 machine_scope.go:185] miyadav-jpfdm-worker-westus-rdl6b: patching machine
I0424 10:34:15.820369       1 controller.go:419] miyadav-jpfdm-worker-westus-rdl6b: going into phase "Provisioned"

Comment 10 Milind Yadav 2020-04-24 10:45:22 UTC
It did not got stuck into "failed" status this time .. #9

Comment 11 Alberto 2020-04-24 11:49:43 UTC
Let's consider the "failed" status a transient thing and leave it aside.

To get to the path that originated this BZ, the node needs to go unreachable.

Once you have a running cluster, can you please:
1 - Enforce a node to go unreachable. E.g killing the kubelet or in AWS you can just stop the instance in the console.
2 - Delete the machine backing the unreachable node via kubectl delete
3 - Share your steps with the name of the machine deleted and attach a file with machine controller logs here

Comment 12 Milind Yadav 2020-04-24 12:18:37 UTC
Thanks Alberto , followed the steps on  #11 but on Azure 

NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.5.0-0.nightly-2020-04-21-103613   True        False         25m     Cluster version is 4.5.0-0.nightly-2020-04-21-103613

Reproducible Always.


Steps to Reproduce:
1.Stopped the machine from Iaas console , to make the kubelet die .
Instance stopped successfully 

2. Delete a machine
oc delete machine <machine-name that was stopped from Iaas>
Machine terminated successfully 


3. oc logs -f  machine-api-controllers-788f58b4-jl9bj -c machine-controller 
Actual & Expected logs :

[miyadav@miyadav bug1804635]$ oc logs machine-api-controllers-788f58b4-jl9bj -c machine-controller | grep "draining will wait"
I0424 12:08:31.625026       1 controller.go:361] "miyadav-jpfdm-worker-westus-rdl6b": Node "miyadav-jpfdm-worker-westus-rdl6b" is unreachable, draining will wait 300 seconds after pod is signalled for deletion and skip after it
I0424 12:08:32.502973       1 controller.go:361] "miyadav-jpfdm-worker-westus-rdl6b": Node "miyadav-jpfdm-worker-westus-rdl6b" is unreachable, draining will wait 300 seconds after pod is signalled for deletion and skip after it
I0424 12:08:52.481719       1 controller.go:361] "miyadav-jpfdm-worker-westus-rdl6b": Node "miyadav-jpfdm-worker-westus-rdl6b" is unreachable, draining will wait 300 seconds after pod is signalled for deletion and skip after it
[miyadav@miyadav bug1804635]$ 


Additional info :
Here is the pastebin since you asked for full logs .
http://pastebin.test.redhat.com/858849

Comment 13 Milind Yadav 2020-04-24 12:21:15 UTC
Moved to VERIFIED

Comment 15 errata-xmlrpc 2020-08-04 18:01:08 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (OpenShift Container Platform 4.5 image release advisory), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:2409


Note You need to log in before you can comment on or make changes to this bug.