Bug 1665779 - [cloud] Current logging in the machineset controller using klog does not work
Summary: [cloud] Current logging in the machineset controller using klog does not work
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Cloud Compute
Version: unspecified
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 4.1.0
Assignee: Jan Chaloupka
QA Contact: sunzhaohua
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-01-14 01:37 UTC by sunzhaohua
Modified: 2019-06-04 10:41 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-06-04 10:41:49 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2019:0758 None None None 2019-06-04 10:41:55 UTC

Description sunzhaohua 2019-01-14 01:37:18 UTC
Description of problem:
Current logging in the machineset controller using klog does not work

Version-Release number of selected component (if applicable):
$ oc get clusterversion
NAME      VERSION   AVAILABLE   PROGRESSING   SINCE     STATUS
version   4.0.0-9   True        False         35s       Cluster version is 4.0.0-9

How reproducible:
Always

Steps to Reproduce:
1. Create a new machine
2. Check machine-controller logs if no event is triggered no reconciling logs	
3.

Actual results:
When creating a new machine no reconciling logs.
$ oc logs -f clusterapi-manager-controllers-5b4996fb88-bzst7 -c machine-controller
I0111 05:30:50.471472       1 actuator.go:353] checking if machine exists
I0111 05:30:50.475524       1 utils.go:151] Falling to providerConfig
I0111 05:30:50.532829       1 actuator.go:361] instance does not exist
I0111 05:30:50.532888       1 actuator.go:109] creating machine
I0111 05:30:50.532899       1 utils.go:151] Falling to providerConfig
I0111 05:30:50.558408       1 instances.go:44] no stopped instances found for machine zhsun-worker-us-east-2a
I0111 05:30:50.575114       1 instances.go:131] Using AMI ami-085b89e82b74a76b5
I0111 05:30:50.575200       1 instances.go:73] Describing security groups based on filters
I0111 05:30:51.046444       1 instances.go:108] Describing subnets based on filters
I0111 05:30:52.087296       1 actuator.go:450] updating status
I0111 05:30:52.088099       1 actuator.go:494] finished calculating AWS status
I0111 05:30:52.088313       1 actuator.go:143] machine status has changed, updating
I0111 05:30:52.101684       1 actuator.go:512] instance state still pending, returning an error to requeue
I0111 05:30:52.105620       1 actuator.go:353] checking if machine exists
I0111 05:30:52.105763       1 utils.go:151] Falling to providerConfig
I0111 05:30:52.322515       1 actuator.go:366] instance exists as "i-056397970f9c56899"
I0111 05:30:52.322617       1 actuator.go:283] updating machine
I0111 05:30:52.322628       1 utils.go:151] Falling to providerConfig
I0111 05:30:52.323170       1 actuator.go:291] obtaining EC2 client for region
I0111 05:30:52.366060       1 actuator.go:307] found 1 instances for machine
I0111 05:30:52.366086       1 actuator.go:325] instance found
I0111 05:30:52.366097       1 actuator.go:450] updating status
I0111 05:30:52.366217       1 actuator.go:494] finished calculating AWS status
I0111 05:30:52.366395       1 actuator.go:152] status unchanged


Expected results:
When creating a new machine, machine-controller output reconciling logs like bellow. If no event is triggered no reconciling logs.
1105 09:34:31.090049       1 controller.go:113] Running reconcile Machine for aws-actuator-testing-machine
I1105 09:34:31.090151       1 actuator.go:548] checking if machine exists
I1105 09:34:31.171290       1 actuator.go:556] instance does not exist
I1105 09:34:31.171454       1 controller.go:175] Reconciling machine object aws-actuator-testing-machine triggers idempotent create.
I1105 09:34:31.171603       1 actuator.go:110] creating machine
I1105 09:34:31.180079       1 actuator.go:299] Using AMI ami-2fb42b39
W1105 09:34:31.180238       1 actuator.go:345] More than one subnet id returned, only first one will be used
I1105 09:34:32.405188       1 actuator.go:630] updating status
I1105 09:34:32.405444       1 actuator.go:673] finished calculating AWS status
I1105 09:34:32.405793       1 actuator.go:142] machine status has changed, updating
I1105 09:34:32.429694       1 actuator.go:692] instance state still pending, returning an error to requeue
W1105 09:34:32.429796       1 controller.go:177] unable to create machine aws-actuator-testing-machine: requeue in: 20s
I1105 09:34:32.429849       1 controller.go:179] Actuator returned requeue-after error: requeue in: 20s
I1105 09:34:32.429968       1 controller.go:113] Running reconcile Machine for aws-actuator-testing-machine
I1105 09:34:32.430060       1 actuator.go:548] checking if machine exists
I1105 09:34:32.682006       1 actuator.go:561] instance exists as "i-036cbba76762d1ffc"
I1105 09:34:32.682121       1 controller.go:163] Reconciling machine object aws-actuator-testing-machine triggers idempotent update.
I1105 09:34:32.682397       1 actuator.go:483] updating machine
I1105 09:34:32.683078       1 actuator.go:492] obtaining EC2 client for region
I1105 09:34:32.761475       1 actuator.go:508] found 1 instances for machine
I1105 09:34:32.761514       1 actuator.go:526] instance found
I1105 09:34:32.761531       1 actuator.go:630] updating status
I1105 09:34:32.761616       1 actuator.go:673] finished calculating AWS status
I1105 09:34:32.761791       1 actuator.go:151] status unchanged
I1105 09:34:32.761808       1 actuator.go:692] instance state still pending, returning an error to requeue
I1105 09:34:32.761822       1 controller.go:167] Actuator returned requeue-after error: requeue in: 20s


Additional info:

Comment 1 Jan Chaloupka 2019-01-14 09:56:09 UTC
Downstream PR: https://github.com/openshift/cluster-api-provider-aws/pull/141

Comment 2 Jan Chaloupka 2019-01-14 11:06:41 UTC
Upstream PR: https://github.com/kubernetes-sigs/cluster-api/pull/677

Comment 3 sunzhaohua 2019-01-18 07:11:48 UTC
Verified.

$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE     STATUS
version   4.0.0-0.nightly-2019-01-17-185315   True        False         1h        Cluster version is 4.0.0-0.nightly-2019-01-17-185315

Create a new machine, check logs.

$ oc logs -f clusterapi-manager-controllers-64584db79-d2hq5 -c machine-controller
I0118 07:09:43.902388       1 controller.go:113] Running reconcile Machine for zhsun-worker-us-east-2a
I0118 07:09:43.907973       1 actuator.go:401] checking if machine exists
I0118 07:09:43.956277       1 actuator.go:409] instance does not exist
I0118 07:09:43.961396       1 controller.go:181] Reconciling machine object zhsun-worker-us-east-2a triggers idempotent create.
I0118 07:09:43.961504       1 actuator.go:110] creating machine
I0118 07:09:43.983946       1 instances.go:44] no stopped instances found for machine zhsun-worker-us-east-2a
I0118 07:09:43.988827       1 instances.go:141] Using AMI ami-085b89e82b74a76b5
I0118 07:09:43.988926       1 instances.go:73] Describing security groups based on filters
I0118 07:09:44.069888       1 instances.go:118] Describing subnets based on filters
I0118 07:09:44.877535       1 actuator.go:498] updating status
I0118 07:09:44.877665       1 actuator.go:542] finished calculating AWS status
I0118 07:09:44.877794       1 actuator.go:144] machine status has changed, updating
I0118 07:09:44.887182       1 actuator.go:560] instance state still pending, returning an error to requeue
W0118 07:09:44.887205       1 controller.go:183] unable to create machine zhsun-worker-us-east-2a: requeue in: 20s
I0118 07:09:44.887225       1 controller.go:185] Actuator returned requeue-after error: requeue in: 20s
I0118 07:09:44.887584       1 controller.go:113] Running reconcile Machine for zhsun-worker-us-east-2a
I0118 07:09:44.887618       1 actuator.go:401] checking if machine exists
I0118 07:09:45.080442       1 actuator.go:414] instance exists as "i-06ff9bddbb6ea21ca"
I0118 07:09:45.080475       1 controller.go:170] Reconciling machine object zhsun-worker-us-east-2a triggers idempotent update.
I0118 07:09:45.080518       1 actuator.go:331] updating machine
I0118 07:09:45.080630       1 actuator.go:339] obtaining EC2 client for region
I0118 07:09:45.119829       1 actuator.go:355] found 1 instances for machine
I0118 07:09:45.124140       1 actuator.go:373] instance found
I0118 07:09:45.124159       1 actuator.go:498] updating status
I0118 07:09:45.124255       1 actuator.go:542] finished calculating AWS status
I0118 07:09:45.124387       1 actuator.go:153] status unchanged
I0118 07:09:45.124399       1 actuator.go:560] instance state still pending, returning an error to requeue
I0118 07:09:45.124413       1 controller.go:173] Actuator returned requeue-after error: requeue in: 20s


I0118 07:10:04.887503       1 controller.go:113] Running reconcile Machine for zhsun-worker-us-east-2a
I0118 07:10:04.887568       1 actuator.go:401] checking if machine exists
I0118 07:10:05.011314       1 actuator.go:414] instance exists as "i-06ff9bddbb6ea21ca"
I0118 07:10:05.011348       1 controller.go:170] Reconciling machine object zhsun-worker-us-east-2a triggers idempotent update.
I0118 07:10:05.011395       1 actuator.go:331] updating machine
I0118 07:10:05.011503       1 actuator.go:339] obtaining EC2 client for region
I0118 07:10:05.052654       1 actuator.go:355] found 1 instances for machine
I0118 07:10:05.052681       1 actuator.go:373] instance found
I0118 07:10:05.052692       1 actuator.go:498] updating status
I0118 07:10:05.052767       1 actuator.go:542] finished calculating AWS status
I0118 07:10:05.052926       1 actuator.go:144] machine status has changed, updating
I0118 07:10:05.061950       1 controller.go:113] Running reconcile Machine for zhsun-worker-us-east-2a
I0118 07:10:05.062068       1 actuator.go:401] checking if machine exists
I0118 07:10:05.096972       1 actuator.go:414] instance exists as "i-06ff9bddbb6ea21ca"
I0118 07:10:05.096998       1 controller.go:170] Reconciling machine object zhsun-worker-us-east-2a triggers idempotent update.
I0118 07:10:05.097028       1 actuator.go:331] updating machine
I0118 07:10:05.097114       1 actuator.go:339] obtaining EC2 client for region
I0118 07:10:05.139602       1 actuator.go:355] found 1 instances for machine
I0118 07:10:05.139716       1 actuator.go:373] instance found
I0118 07:10:05.139782       1 actuator.go:498] updating status
I0118 07:10:05.139919       1 actuator.go:542] finished calculating AWS status
I0118 07:10:05.140046       1 actuator.go:153] status unchanged

Comment 6 errata-xmlrpc 2019-06-04 10:41:49 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, 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-2019:0758


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