Bug 2094335

Summary: [Nutanix] - debug logs are enabled by default in machine-controller
Product: OpenShift Container Platform Reporter: Milind Yadav <miyadav>
Component: Cloud ComputeAssignee: Yanhua Li <yanhli>
Cloud Compute sub component: Other Providers QA Contact: Milind Yadav <miyadav>
Status: CLOSED ERRATA Docs Contact:
Severity: high    
Priority: high CC: sid.shukla, sishukla, yanhli
Version: 4.11   
Target Milestone: ---   
Target Release: 4.11.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-08-10 11:16:50 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Milind Yadav 2022-06-07 12:19:28 UTC 
Description of problem:Seems like debug log is enabled by default for machine-controller pods 


Version-Release number of selected component (if applicable):
4.11.0-0.nightly-2022-06-06-025509

How reproducible:
Always

Steps to Reproduce:
1.scale machineset  
[miyadav@miyadav nutanix]$ oc get machineset 
NAME                     DESIRED   CURRENT   READY   AVAILABLE   AGE
huliu-n13-sz54h-1        1         1         1       1           7h16m
huliu-n13-sz54h-worker   2         2         2       2           9h
[miyadav@miyadav nutanix]$ oc scale machineset huliu-n13-sz54h-worker --replicas 3 
machineset.machine.openshift.io/huliu-n13-sz54h-worker scaled



Expected and actual 
Machineset scaled successfully 

2.Monitor machinecontroller logs 

.
.
.
.
2022/06/07 12:13:17 [DEBUG] GET /api/nutanix/v3/vms/23b8a5b4-b133-41a1-985e-099a1f319677 HTTP/1.1
Host: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440
Accept: application/json
Authorization: Basic c2dhbzpqP1MzdHomeA==
Content-Type: application/json
User-Agent: nutanix/v3


2022/06/07 12:13:17 [DEBUG] HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Security-Policy: default-src 'self' https://*.nutanix.com; script-src 'self' 'unsafe-inline' 'unsafe-eval'; style-src 'self' 'unsafe-inline'; connect-src 'self' wss: https://downloads.frame.nutanix.com https://downloads.frame.nutanix.us; img-src 'self' blob: data:; frame-src 'self' https://*.nutanix.com blob: data:
Content-Type: application/json
Date: Tue, 07 Jun 2022 12:13:17 GMT
Server: envoy
Set-Cookie: NTNX_IGW_SESSION=eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiJ9.eyJ1c2VyX3Byb2ZpbGUiOiJ7XCJ1c2VybmFtZVwiOiBcInNnYW9cIiwgXCJkb21haW5cIjogbnVsbCwgXCJsZWdhY3lfYWRtaW5fYXV0aG9yaXRpZXNcIjogW1wiUk9MRV9DTFVTVEVSX0FETUlOXCIsIFwiUk9MRV9DTFVTVEVSX1ZJRVdFUlwiLCBcIlJPTEVfTVVMVElDTFVTVEVSX0FETUlOXCJdLCBcImF1dGhlbnRpY2F0ZWRcIjogdHJ1ZSwgXCJfcGVybWFuZW50XCI6IHRydWUsIFwicm9sZXNcIjogW1wiUHJpc20gQWRtaW5cIiwgXCJQcmlzbSBWaWV3ZXJcIl0sIFwibG9nX3V1aWRcIjogXCIyMTYyZTg3Ny1jZmEyLTRlMTQtOGFjNi0xNjNiNzNlMmE5ODRcIiwgXCJ1c2VydHlwZVwiOiBcImxvY2FsXCIsIFwiYXBwX2RhdGFcIjoge30sIFwiYXV0aF9pbmZvXCI6IHtcInVzZXJuYW1lXCI6IFwic2dhb1wiLCBcInJlbW90ZV9hdXRob3JpemF0aW9uXCI6IG51bGwsIFwidXNlcl9ncm91cF91dWlkc1wiOiBudWxsLCBcInJlbW90ZV9hdXRoX2pzb25cIjogbnVsbCwgXCJzZXJ2aWNlX25hbWVcIjogbnVsbCwgXCJ0b2tlbl9hdWRpZW5jZVwiOiBudWxsLCBcInRva2VuX2lzc3VlclwiOiBudWxsLCBcInVzZXJfdXVpZFwiOiBcIjYyZjExNjk4LTk3ZTQtNTFiMy04OTkyLTUyNTllM2NjMzNjNlwiLCBcInRlbmFudF91dWlkXCI6IFwiMDAwMDAwMDAtMDAwMC0wMDAwLTAwMDAtMDAwMDAwMDAwMDAwXCJ9fSIsImp0aSI6IjdjYWQzMzExLWQxNDgtMzUwZi1hZTFjLWQ5ZjZmNDU2NWFlZiIsImlzcyI6IkF0aGVuYSIsImlhdCI6MTY1NDYwMzk5NywiZXhwIjoxNjU0NjA0ODk3fQ.Eriz3bu4X6jLcjhV0-EpHhz6_5CgSM1qM2zXW7o_1mwnXVaBGayX15UyP19v3hFWd3J5duJMlKP2StuyOq40mImjHu5XlLwj07obZfhUTdYg6DReUcD_VEWcZHwecatIffWJ9mxoH4JCETx9CcPo-Xtyr2mzMmKWhPsCC0ikC822_xHZ9ZIVzY07KA0Nk1a2Huq_AZoIqXaoe0q6_asM8cEYdxNZ1_c-dzsssJmU49dz2SQtmduPX6n7kJXhT3G4buN0e3CH2-toZDTnkIuYaw_md35OjGxQ0sUBPIEifydxphe6mMgSqdz0Ilu6OrAOmI7ImXWm3RPww7QyT_0YbA; Expires=Tue, 07-Jun-2022 12:28:17 GMT; HttpOnly; Path=/; SameSite=Lax
Strict-Transport-Security: max-age=8640000:includeSubdomains
Vary: Accept-Encoding
X-Content-Type-Options: nosniff
X-Dns-Prefetch-Control: off
X-Envoy-Upstream-Service-Time: 307
X-Frame-Options: SAMEORIGIN
X-Ntnx-Env: pc
X-Ntnx-Product: pc.2022.1
X-Permitted-Cross-Domain-Policies: master-only
X-Xss-Protection: 1; mode=block
.
.
.

Expected :
Info logs should be present 

Actual :
Too much logging info being pushed seems debug log is on for machine-controller 


Additional info:

this is not happening for other containers like machine-heathcheck-controller , nodelink-controller and others .
Comment 1 Sid Shukla 2022-06-13 13:19:58 UTC 
Can you add some more info?
Comment 2 Milind Yadav 2022-06-14 02:59:20 UTC 
@Sid , let me know are the comments marked as private not visible to you ? I changed it now , Please confirm if that was the case or you want any other info ?
Comment 3 Sid Shukla 2022-06-14 11:57:25 UTC 
@Milind; thanks! the comment is visible now.
Comment 4 Joel Speed 2022-06-16 13:10:31 UTC 
@yanhli Could you please take a look at this bug?
Comment 7 Milind Yadav 2022-06-23 10:25:36 UTC 
Validated on - [miyadav@miyadav nutanix]$ oc get clusterversion 
NAME      VERSION                              AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.11.0-0.nightly-2022-06-22-235234   True        False         33m     Cluster version is 4.11.0-0.nightly-2022-06-22-235234





Followed same steps as mentioned in comment#1 , debug logs not seen as default logs : 
After scaling machineset 

[miyadav@miyadav nutanix]$ oc log -f machine-api-controllers-7879d9c49-lx94h -c machine-controller 

.
.
.
.
.
I0623 10:15:48.784514       1 actuator.go:114] miyadav-2306nu-xnx5w-worker-77frw: actuator checking if machine exists
I0623 10:15:48.784665       1 utils.go:186] Successfully set the PrismCentral credentials to the clientOptions to create the Prism Central client.
I0623 10:15:48.784677       1 client.go:55] To create nutanixClient with creds: (url: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440, insecure: false, debug-log: false)
I0623 10:15:48.784687       1 vm.go:301] Checking if VM with UUID b9bb7e9a-de2f-41de-a024-0acb3d06a328 exists.
I0623 10:15:48.992834       1 reconciler.go:228] miyadav-2306nu-xnx5w-worker-77frw: vm exists
I0623 10:15:48.992922       1 controller.go:305] miyadav-2306nu-xnx5w-worker-77frw: reconciling machine triggers idempotent update
I0623 10:15:48.992950       1 actuator.go:130] miyadav-2306nu-xnx5w-worker-77frw: actuator updating machine
I0623 10:15:48.993076       1 utils.go:186] Successfully set the PrismCentral credentials to the clientOptions to create the Prism Central client.
I0623 10:15:48.993107       1 client.go:55] To create nutanixClient with creds: (url: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440, insecure: false, debug-log: false)
I0623 10:15:48.993136       1 reconciler.go:80] miyadav-2306nu-xnx5w-worker-77frw: updating machine
I0623 10:15:48.993165       1 vm.go:301] Checking if VM with UUID b9bb7e9a-de2f-41de-a024-0acb3d06a328 exists.
I0623 10:15:49.177449       1 reconciler.go:306] miyadav-2306nu-xnx5w-worker-77frw: updating machine providerID
I0623 10:15:49.177483       1 reconciler.go:264] miyadav-2306nu-xnx5w-worker-77frw: ProviderID already set in the machine Spec with value: nutanix://b9bb7e9a-de2f-41de-a024-0acb3d06a328
I0623 10:15:49.185905       1 reconciler.go:295] miyadav-2306nu-xnx5w-worker-77frw: The node "miyadav-2306nu-xnx5w-worker-77frw" spec.providerID is set to: nutanix://b9bb7e9a-de2f-41de-a024-0acb3d06a328
I0623 10:15:49.185987       1 reconciler.go:320] miyadav-2306nu-xnx5w-worker-77frw: updated machine instance state annotations (machine.openshift.io/instance-type: AHV), (machine.openshift.io/instance-state: COMPLETE), (machine.openshift.io/instance-power-state: ON)
I0623 10:15:49.186016       1 machine_scope.go:211] miyadav-2306nu-xnx5w-worker-77frw: Updating providerStatus
I0623 10:15:49.186044       1 reconciler.go:135] miyadav-2306nu-xnx5w-worker-77frw: updated machine vm state
I0623 10:15:49.186070       1 machine_scope.go:154] miyadav-2306nu-xnx5w-worker-77frw: patching machine
I0623 10:15:49.209421       1 controller.go:426] miyadav-2306nu-xnx5w-worker-77frw: going into phase "Running"
I0623 10:15:49.209526       1 logr.go:252] events "msg"="Normal"  "message"="Updated Machine miyadav-2306nu-xnx5w-worker-77frw" "object"={"kind":"Machine","namespace":"openshift-machine-api","name":"miyadav-2306nu-xnx5w-worker-77frw","uid":"1336716a-597c-47b9-a671-c90b4d159b85","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"43570"} "reason"="Update"
I0623 10:15:49.217212       1 controller.go:179] miyadav-2306nu-xnx5w-worker-77frw: reconciling Machine
I0623 10:15:49.217229       1 actuator.go:114] miyadav-2306nu-xnx5w-worker-77frw: actuator checking if machine exists
I0623 10:15:49.217296       1 utils.go:186] Successfully set the PrismCentral credentials to the clientOptions to create the Prism Central client.
I0623 10:15:49.217305       1 client.go:55] To create nutanixClient with creds: (url: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440, insecure: false, debug-log: false)
I0623 10:15:49.217313       1 vm.go:301] Checking if VM with UUID b9bb7e9a-de2f-41de-a024-0acb3d06a328 exists.
I0623 10:15:49.400622       1 reconciler.go:228] miyadav-2306nu-xnx5w-worker-77frw: vm exists
I0623 10:15:49.400642       1 controller.go:305] miyadav-2306nu-xnx5w-worker-77frw: reconciling machine triggers idempotent update
I0623 10:15:49.400647       1 actuator.go:130] miyadav-2306nu-xnx5w-worker-77frw: actuator updating machine
I0623 10:15:49.400737       1 utils.go:186] Successfully set the PrismCentral credentials to the clientOptions to create the Prism Central client.
I0623 10:15:49.400748       1 client.go:55] To create nutanixClient with creds: (url: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440, insecure: false, debug-log: false)
I0623 10:15:49.400763       1 reconciler.go:80] miyadav-2306nu-xnx5w-worker-77frw: updating machine
I0623 10:15:49.400767       1 vm.go:301] Checking if VM with UUID b9bb7e9a-de2f-41de-a024-0acb3d06a328 exists.
I0623 10:15:49.583315       1 reconciler.go:306] miyadav-2306nu-xnx5w-worker-77frw: updating machine providerID
I0623 10:15:49.583410       1 reconciler.go:264] miyadav-2306nu-xnx5w-worker-77frw: ProviderID already set in the machine Spec with value: nutanix://b9bb7e9a-de2f-41de-a024-0acb3d06a328
I0623 10:15:49.583466       1 reconciler.go:287] miyadav-2306nu-xnx5w-worker-77frw: The node "miyadav-2306nu-xnx5w-worker-77frw" spec.providerID is already set with value: nutanix://b9bb7e9a-de2f-41de-a024-0acb3d06a328
I0623 10:15:49.583494       1 reconciler.go:320] miyadav-2306nu-xnx5w-worker-77frw: updated machine instance state annotations (machine.openshift.io/instance-type: AHV), (machine.openshift.io/instance-state: COMPLETE), (machine.openshift.io/instance-power-state: ON)
I0623 10:15:49.583519       1 machine_scope.go:211] miyadav-2306nu-xnx5w-worker-77frw: Updating providerStatus
I0623 10:15:49.583564       1 reconciler.go:135] miyadav-2306nu-xnx5w-worker-77frw: updated machine vm state
I0623 10:15:49.583596       1 machine_scope.go:154] miyadav-2306nu-xnx5w-worker-77frw: patching machine
I0623 10:16:19.519533       1 controller.go:179] miyadav-2306nu-xnx5w-worker-77frw: reconciling Machine
I0623 10:16:19.521004       1 actuator.go:114] miyadav-2306nu-xnx5w-worker-77frw: actuator checking if machine exists
I0623 10:16:19.521480       1 utils.go:186] Successfully set the PrismCentral credentials to the clientOptions to create the Prism Central client.
I0623 10:16:19.521668       1 client.go:55] To create nutanixClient with creds: (url: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440, insecure: false, debug-log: false)
I0623 10:16:19.521728       1 vm.go:301] Checking if VM with UUID b9bb7e9a-de2f-41de-a024-0acb3d06a328 exists.
I0623 10:16:19.535688       1 controller.go:57] controllers/MachineSet "msg"="Reconciling" "machineset"="miyadav-2306nu-xnx5w-worker" "namespace"="openshift-machine-api" 
I0623 10:16:19.694118       1 reconciler.go:228] miyadav-2306nu-xnx5w-worker-77frw: vm exists
I0623 10:16:19.694228       1 controller.go:305] miyadav-2306nu-xnx5w-worker-77frw: reconciling machine triggers idempotent update
I0623 10:16:19.694483       1 actuator.go:130] miyadav-2306nu-xnx5w-worker-77frw: actuator updating machine
I0623 10:16:19.694681       1 utils.go:186] Successfully set the PrismCentral credentials to the clientOptions to create the Prism Central client.
I0623 10:16:19.694743       1 client.go:55] To create nutanixClient with creds: (url: prismcentral.lts-cluster.nutanix-dev.devcluster.openshift.com:9440, insecure: false, debug-log: false)
I0623 10:16:19.694777       1 reconciler.go:80] miyadav-2306nu-xnx5w-worker-77frw: updating machine
I0623 10:16:19.694840       1 vm.go:301] Checking if VM with UUID b9bb7e9a-de2f-41de-a024-0acb3d06a328 exists.
I0623 10:16:19.866328       1 reconciler.go:306] miyadav-2306nu-xnx5w-worker-77frw: updating machine providerID
I0623 10:16:19.866353       1 reconciler.go:264] miyadav-2306nu-xnx5w-worker-77frw: ProviderID already set in the machine Spec with value: nutanix://b9bb7e9a-de2f-41de-a024-0acb3d06a328
I0623 10:16:19.866397       1 reconciler.go:287] miyadav-2306nu-xnx5w-worker-77frw: The node "miyadav-2306nu-xnx5w-worker-77frw" spec.providerID is already set with value: nutanix://b9bb7e9a-de2f-41de-a024-0acb3d06a328
I0623 10:16:19.866407       1 reconciler.go:320] miyadav-2306nu-xnx5w-worker-77frw: updated machine instance state annotations (machine.openshift.io/instance-type: AHV), (machine.openshift.io/instance-state: COMPLETE), (machine.openshift.io/instance-power-state: ON)
I0623 10:16:19.866414       1 machine_scope.go:211] miyadav-2306nu-xnx5w-worker-77frw: Updating providerStatus
I0623 10:16:19.866422       1 reconciler.go:135] miyadav-2306nu-xnx5w-worker-77frw: updated machine vm state
.
.
.
.


Additional info:
Moved to VERIFIED
Comment 9 errata-xmlrpc 2022-08-10 11:16:50 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 (Important: OpenShift Container Platform 4.11.0 bug fix and security update), 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/RHSA-2022:5069
Comment 10 Red Hat Bugzilla 2023-09-15 01:55:37 UTC 
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 365 days