Chore - Fix double trace IDs in the logs when initialising k8s orchestrator #3234

kolluria · 2025-03-25T09:17:42Z

What this PR does / why we need it:

When vsphere-csi-controller container is spun up, we're making two invocations to GetNewContextWithLogger which is resulting in the logs to have two TraceIDs.

The first invocation occurs in main.go and the second invocation in BeforeServe.

This PR removes the second invocation. Additionally, BeforeServe method is refactored for better readability.

Which issue this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close that issue when PR gets merged): fixes #

Testing done:

Logs without this change

2025-03-27T17:39:02.001Z	INFO	logger/logger.go:41	Setting default log level to :"DEVELOPMENT"
2025-03-27T17:39:02.006Z	INFO	vsphere-csi/main.go:56	Version : 	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33"}
2025-03-27T17:39:02.007Z	INFO	commonco/utils.go:41	Defaulting feature states configmap name to "csi-feature-states"	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33"}
2025-03-27T17:39:02.010Z	INFO	commonco/utils.go:45	Defaulting feature states configmap namespace to "vmware-system-csi"	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33"}
2025-03-27T17:39:02.010Z	DEBUG	commonco/utils.go:106	Container orchestrator init params: {SupervisorFeatureStatesConfigInfo:{Name:csi-feature-states Namespace:vmware-system-csi} ServiceMode:controller OperationMode:}	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33"}
2025-03-27T17:39:02.010Z	INFO	vsphere-csi/main.go:73	Enable logging off for vCenter sessions on exit	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33"}
2025-03-27T17:39:02.011Z	INFO	logger/logger.go:41	Setting default log level to :"DEVELOPMENT"
2025-03-27T17:39:02.012Z	INFO	k8sorchestrator/k8sorchestrator.go:254	Initializing k8sOrchestratorInstance	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.021Z	DEBUG	kubernetes/kubernetes.go:107	Kubeconfig flag is set but empty, checking environment variable value	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.022Z	DEBUG	kubernetes/kubernetes.go:115	Kubeconfig path obtained from environment variable "KUBECONFIG": ""	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.022Z	DEBUG	kubernetes/kubernetes.go:120	No Kubeconfig path found, either from environment variable or flag	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.022Z	DEBUG	kubernetes/kubernetes.go:82	k8s client using in-cluster config	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.023Z	DEBUG	kubernetes/kubernetes.go:435	Setting client QPS to 200.000000 and Burst to 200.	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.039Z	DEBUG	kubernetes/kubernetes.go:107	Kubeconfig flag is set but empty, checking environment variable value	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.040Z	DEBUG	kubernetes/kubernetes.go:115	Kubeconfig path obtained from environment variable "KUBECONFIG": ""	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.040Z	DEBUG	kubernetes/kubernetes.go:120	No Kubeconfig path found, either from environment variable or flag	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.040Z	DEBUG	kubernetes/kubernetes.go:82	k8s client using in-cluster config	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.040Z	DEBUG	kubernetes/kubernetes.go:435	Setting client QPS to 200.000000 and Burst to 200.	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.045Z	INFO	kubernetes/informers.go:86	Created new informer factory for in-cluster client	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.101Z	INFO	k8sorchestrator/k8sorchestrator.go:584	New supervisor feature states values stored successfully: map[WCP_VMService_BYOK:false async-query-volume:true block-volume-snapshot:true cns-unregister-volume:false cnsmgr-suspend-create-volume:true csi-sv-feature-states-replication:true fake-attach:true file-volume:true improved-csi-idempotency:true list-volumes:true online-volume-extend:true sibling-replica-bound-pvc-check:true storage-quota-m2:true tkgs-ha:true trigger-csi-fullsync:false vdpp-on-stretched-supervisor:true volume-extend:true volume-health:true workload-domain-isolation:true]	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.103Z	DEBUG	k8sorchestrator/k8sorchestrator.go:921	Initializing volume ID to PVC name map	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.119Z	DEBUG	k8sorchestrator/k8sorchestrator.go:1425	Initializing volumeName/pvName to node name map	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.119Z	DEBUG	k8sorchestrator/k8sorchestrator.go:1597	Initializing node ID to node name map	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}
2025-03-27T17:39:02.119Z	INFO	k8sorchestrator/k8sorchestrator.go:338	k8sOrchestratorInstance initialized	{"TraceId": "fd270fce-aec6-4bba-ab71-dfc4ec481f33", "TraceId": "61c35d1b-bd43-4454-9cde-f480002bfc88"}

Logs with this change

2025-03-27T18:09:12.441Z	INFO	logger/logger.go:41	Setting default log level to :"DEVELOPMENT"
2025-03-27T18:09:12.441Z	INFO	vsphere-csi/main.go:56	Version : unknown	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.441Z	INFO	commonco/utils.go:41	Defaulting feature states configmap name to "csi-feature-states"	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.441Z	INFO	commonco/utils.go:45	Defaulting feature states configmap namespace to "vmware-system-csi"	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.441Z	DEBUG	commonco/utils.go:106	Container orchestrator init params: {SupervisorFeatureStatesConfigInfo:{Name:csi-feature-states Namespace:vmware-system-csi} ServiceMode:controller OperationMode:}	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.441Z	INFO	vsphere-csi/main.go:73	Enable logging off for vCenter sessions on exit	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.442Z	INFO	k8sorchestrator/k8sorchestrator.go:254	Initializing k8sOrchestratorInstance	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.442Z	DEBUG	kubernetes/kubernetes.go:107	Kubeconfig flag is set but empty, checking environment variable value	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.442Z	DEBUG	kubernetes/kubernetes.go:115	Kubeconfig path obtained from environment variable "KUBECONFIG": ""	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.442Z	DEBUG	kubernetes/kubernetes.go:120	No Kubeconfig path found, either from environment variable or flag	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.442Z	DEBUG	kubernetes/kubernetes.go:82	k8s client using in-cluster config	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.442Z	DEBUG	kubernetes/kubernetes.go:435	Setting client QPS to 200.000000 and Burst to 200.	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.443Z	DEBUG	kubernetes/kubernetes.go:107	Kubeconfig flag is set but empty, checking environment variable value	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.449Z	DEBUG	kubernetes/kubernetes.go:115	Kubeconfig path obtained from environment variable "KUBECONFIG": ""	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.449Z	DEBUG	kubernetes/kubernetes.go:120	No Kubeconfig path found, either from environment variable or flag	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.449Z	DEBUG	kubernetes/kubernetes.go:82	k8s client using in-cluster config	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.449Z	DEBUG	kubernetes/kubernetes.go:435	Setting client QPS to 200.000000 and Burst to 200.	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.481Z	INFO	kubernetes/informers.go:86	Created new informer factory for in-cluster client	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.499Z	INFO	k8sorchestrator/k8sorchestrator.go:584	New supervisor feature states values stored successfully: map[WCP_VMService_BYOK:false async-query-volume:true block-volume-snapshot:true cns-unregister-volume:false cnsmgr-suspend-create-volume:true csi-sv-feature-states-replication:true fake-attach:true file-volume:true improved-csi-idempotency:true list-volumes:true online-volume-extend:true sibling-replica-bound-pvc-check:true storage-quota-m2:true tkgs-ha:true trigger-csi-fullsync:false vdpp-on-stretched-supervisor:true volume-extend:true volume-health:true workload-domain-isolation:true]	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.499Z	DEBUG	k8sorchestrator/k8sorchestrator.go:921	Initializing volume ID to PVC name map	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.499Z	DEBUG	k8sorchestrator/k8sorchestrator.go:1425	Initializing volumeName/pvName to node name map	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.499Z	DEBUG	k8sorchestrator/k8sorchestrator.go:1597	Initializing node ID to node name map	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}
2025-03-27T18:09:12.499Z	INFO	k8sorchestrator/k8sorchestrator.go:338	k8sOrchestratorInstance initialized	{"TraceId": "25727614-1c77-4a77-930c-4d1ccda5fecd"}

Special notes for your reviewer:

Release note:

k8s-ci-robot · 2025-03-25T09:17:53Z

Hi @kolluria. Thanks for your PR.

I'm waiting for a kubernetes-sigs member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

deepakkinni · 2025-03-27T22:43:32Z

/ok-to-test

pkg/csi/service/driver.go

kolluria · 2025-04-01T06:28:17Z

/retest-required

Removed the second invocation of NewContextWithLogger in BeforeServe Refactored BeforeServe method

kolluria · 2025-04-17T16:08:57Z

Verified that there is no regression by triggering the precheckin pipeline with my changes -

16:42:30  Ran 13 of 988 Specs in 2423.311 seconds
16:42:30  SUCCESS! -- 13 Passed | 0 Failed | 0 Pending | 975 Skipped
16:42:30  PASS
16:42:30  
16:42:30  Ginkgo ran 1 suite in 41m16.023453068s
16:42:30  Test Suite Passed

deepakkinni · 2025-04-17T20:04:55Z

Nice!

/approve

akankshapanse · 2025-04-18T05:10:45Z

/approve

k8s-ci-robot · 2025-04-18T05:10:52Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: akankshapanse, deepakkinni, kolluria

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [akankshapanse,deepakkinni]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

k8s-ci-robot · 2025-04-25T09:32:50Z

@kolluria: you cannot LGTM your own PR.

In response to this:

/lgtm

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

akankshapanse · 2025-04-25T09:36:21Z

/lgtm

…igs#3234) Removed the second invocation of NewContextWithLogger in BeforeServe Refactored BeforeServe method

* reading multi vc IP export variables at runtime (#3254) * Added snapshot TC for GC (#3251) * vmservice vm domain workload isolation automation code (#3253) * code fix to increase pvc creation timeout and wait time for vm service ns creation (#3249) * Fix double trace IDs when initialising k8s orchestrator (#3234) Removed the second invocation of NewContextWithLogger in BeforeServe Refactored BeforeServe method * add backward compatibility for vm-operator api version v1alpha1 using convesion methods (#3259) --------- Co-authored-by: sipriyaa <[email protected]> Co-authored-by: Bhavya Nayak <[email protected]> Co-authored-by: Satyanarayana Kolluri <[email protected]>

…etes-sigs#3266)

* Reverted the refactoring done as part of #3234 (#3266) * Fix panic on DeletedFinalStateUnknown (#3262) Properly handle DeletedFinalStateUnknown when watching Nodes * fullsync fix: add nil check on claimreference while listing pvs (#3269) * bump up k8s version to 1.33.0 (#3274) --------- Co-authored-by: Satyanarayana Kolluri <[email protected]> Co-authored-by: Jan Šafránek <[email protected]>

k8s-ci-robot requested a review from chethanv28 March 25, 2025 09:17

k8s-ci-robot added the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Mar 25, 2025

k8s-ci-robot requested a review from xing-yang March 25, 2025 09:17

k8s-ci-robot added the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Mar 25, 2025

k8s-ci-robot added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Mar 25, 2025

kolluria changed the title ~~Chore - Refactor BeforeServe method~~ Chore - Fix double trace IDs in the logs Mar 25, 2025

kolluria marked this pull request as draft March 26, 2025 05:47

k8s-ci-robot added the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Mar 26, 2025

kolluria force-pushed the refactor branch 2 times, most recently from 4be8089 to 8e248e4 Compare March 27, 2025 18:28

kolluria changed the title ~~Chore - Fix double trace IDs in the logs~~ Chore - Fix double trace IDs in the logs when initialising k8s orchestrator Mar 27, 2025

kolluria marked this pull request as ready for review March 27, 2025 18:29

k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Mar 27, 2025

k8s-ci-robot requested review from akankshapanse and gnufied March 27, 2025 18:29

k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Mar 27, 2025

akankshapanse reviewed Mar 28, 2025

View reviewed changes

pkg/csi/service/driver.go Show resolved Hide resolved

kolluria force-pushed the refactor branch from 8e248e4 to 9560116 Compare March 28, 2025 07:44

kolluria force-pushed the refactor branch from 9560116 to 1296e3c Compare April 9, 2025 07:55

Fix double trace IDs when initialising k8s orchestrator

3b45dbe

Removed the second invocation of NewContextWithLogger in BeforeServe Refactored BeforeServe method

kolluria force-pushed the refactor branch from 1296e3c to 3b45dbe Compare April 15, 2025 06:47

kolluria requested a review from akankshapanse April 17, 2025 16:14

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Apr 17, 2025

k8s-ci-robot assigned akankshapanse Apr 25, 2025

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 25, 2025

k8s-ci-robot merged commit c853b84 into kubernetes-sigs:master Apr 25, 2025
12 checks passed

kolluria deleted the refactor branch April 25, 2025 09:56

kolluria added a commit to kolluria/vsphere-csi-driver that referenced this pull request Apr 30, 2025

Fix the regression introduced in kubernetes-sigs#3234

53eb3ca

kolluria added a commit to kolluria/vsphere-csi-driver that referenced this pull request Apr 30, 2025

Fix the regression introduced in kubernetes-sigs#3234

9d97c40

kolluria added a commit to kolluria/vsphere-csi-driver that referenced this pull request Apr 30, 2025

Fix the regression introduced in kubernetes-sigs#3234

9b8e448

kolluria mentioned this pull request Apr 30, 2025

Fix the regression introduced in #3234 #3266

Merged

kolluria added a commit to kolluria/vsphere-csi-driver that referenced this pull request May 5, 2025

Reveted the refactoring done as part of kubernetes-sigs#3234

35bf739

kolluria added a commit to kolluria/vsphere-csi-driver that referenced this pull request May 5, 2025

Reverted the refactoring done as part of kubernetes-sigs#3234

09dbd5b

kolluria added a commit to kolluria/vsphere-csi-driver that referenced this pull request May 9, 2025

Reverted the refactoring done as part of kubernetes-sigs#3234

9882f39

k8s-ci-robot pushed a commit that referenced this pull request May 9, 2025

Reverted the refactoring done as part of #3234 (#3266)

7673442

nikhilbarge pushed a commit to nikhilbarge/vsphere-csi-driver that referenced this pull request May 14, 2025

Reverted the refactoring done as part of kubernetes-sigs#3234 (kubern…

a40e072

…etes-sigs#3266)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Chore - Fix double trace IDs in the logs when initialising k8s orchestrator #3234

Chore - Fix double trace IDs in the logs when initialising k8s orchestrator #3234

Uh oh!

kolluria commented Mar 25, 2025 •

edited

Loading

Uh oh!

k8s-ci-robot commented Mar 25, 2025

Uh oh!

deepakkinni commented Mar 27, 2025

Uh oh!

Uh oh!

kolluria commented Apr 1, 2025

Uh oh!

kolluria commented Apr 17, 2025

Uh oh!

deepakkinni commented Apr 17, 2025

Uh oh!

akankshapanse commented Apr 18, 2025

Uh oh!

k8s-ci-robot commented Apr 18, 2025

Uh oh!

k8s-ci-robot commented Apr 25, 2025

Uh oh!

akankshapanse commented Apr 25, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Chore - Fix double trace IDs in the logs when initialising k8s orchestrator #3234

Chore - Fix double trace IDs in the logs when initialising k8s orchestrator #3234

Uh oh!

Conversation

kolluria commented Mar 25, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

k8s-ci-robot commented Mar 25, 2025

Uh oh!

deepakkinni commented Mar 27, 2025

Uh oh!

Uh oh!

kolluria commented Apr 1, 2025

Uh oh!

kolluria commented Apr 17, 2025

Uh oh!

deepakkinni commented Apr 17, 2025

Uh oh!

akankshapanse commented Apr 18, 2025

Uh oh!

k8s-ci-robot commented Apr 18, 2025

Uh oh!

k8s-ci-robot commented Apr 25, 2025

Uh oh!

akankshapanse commented Apr 25, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

kolluria commented Mar 25, 2025 •

edited

Loading