make all logging consistent across the controllers #1812

devigned · 2021-10-29T19:40:37Z

What type of PR is this?
/kind cleanup

What this PR does / why we need it:
This PR cleans up all of the logging inconsistencies and logs everything to the span / composite logger. This PR removes all of the Logger fields and Logger embedded interfaces in scopes, reducing the scope interface footprint.

All log events are added to the appropriate spans in the distributed traces.

Which issue(s) this PR fixes: Fixes #1806

Special notes for your reviewer:
This is a terribly large PR touching almost all of the code base. I'm opening this to illustrate the scope of the changes and would be happy to break it up in whatever way makes the most sense. Please suggest.

Please confirm that if this PR changes any image versions, then that's the sole change this PR makes.

TODOs:

squashed commits
includes documentation
adds unit tests

Release note:

make all logging consistent across the controller

nader-ziada · 2021-11-01T14:04:47Z

nice cleanup 👍

the tests are failing cause of this error:

controllers/azurecluster_controller.go:75:2: ineffectual assignment to ctx (ineffassign)
	ctx, log, done := tele.StartSpanWithLogger(ctx,
	^
controllers/azureidentity_controller.go:56:2: ineffectual assignment to ctx (ineffassign)
	ctx, log, done := tele.StartSpanWithLogger(ctx,

azure/scope/cluster.go

mboersma · 2021-11-01T15:37:05Z

azure/scope/cluster.go

@@ -214,7 +210,7 @@ func (s *ClusterScope) LBSpecs() []azure.LBSpec {

 // RouteTableSpecs returns the node route table.
 func (s *ClusterScope) RouteTableSpecs() []azure.RouteTableSpec {
-	routetables := []azure.RouteTableSpec{}
+	var routetables []azure.RouteTableSpec


Is there any practical difference in how Go treats these two constructs, or is this just for style? (I prefer the var style to which you changed it.)

They are subtly different: https://play.golang.org/p/Yd6jei06m9y. One is an empty slice, the other is nil.

azure/scope/cluster.go

azure/scope/machinepool.go

mboersma · 2021-11-01T15:45:02Z

azure/scope/machinepool.go

@@ -510,12 +507,12 @@ func (m *MachinePoolScope) PatchObject(ctx context.Context) error {

 // Close the MachineScope by updating the machine spec, machine status.
 func (m *MachinePoolScope) Close(ctx context.Context) error {
-	ctx, _, done := tele.StartSpanWithLogger(ctx, "scope.MachinePoolScope.Close")
+	ctx, log, done := tele.StartSpanWithLogger(ctx, "scope.MachinePoolScope.Close")


Do we always want to shadow the ctx argument that was passed in?

Yes'ish, because the ctx that is returned is a new ctx struct which may now contain a correlationID, span, and other values in the bag. We could change the name of the new context, but this ensure that the original is not used below. Only the new ctx would be used. Use of the original is in nearly all cases an error.

Use of the original is in nearly all cases an error.

Got it. Thanks for the clarification.

azure/services/scalesets/mock_scalesets/scalesets_mock.go

controllers/azureidentity_controller.go

exp/controllers/azuremachinepoolmachine_controller_test.go

mboersma · 2021-11-01T18:52:38Z

exp/controllers/common_controller_test.go

@@ -1,109 +0,0 @@
-/*


Are we ceding any important coverage by deleting this (and other) logging-related unit tests?

I don't think so. The tests were not super effective, and as the original author, I'm no longer sold on the fact they verify anything of value.

util/tele/composite_logger.go

devigned · 2021-11-19T21:07:49Z

I believe I've addressed all the feedback.

devigned · 2021-11-22T19:31:48Z

I rebased these changes this morning and looks like all the tests are green. Let me know if you folks see anything that needs to change.

main.go

controllers/azurecluster_controller.go

controllers/azureidentity_controller.go

azure/scope/cluster.go

azure/services/scalesetvms/scalesetvms.go

shysank · 2021-11-24T16:28:33Z

controllers/azuremachine_controller.go

@@ -76,25 +72,28 @@ func NewAzureMachineReconciler(client client.Client, log logr.Logger, recorder r

 // SetupWithManager initializes this controller with a manager.
 func (amr *AzureMachineReconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager, options Options) error {
-	ctx, _, done := tele.StartSpanWithLogger(ctx, "controllers.AzureMachineReconciler.SetupWithManager")
+	ctx, log, done := tele.StartSpanWithLogger(ctx,
+		"controllers.AzureMachineReconciler.SetupWithManager",


clarification:
This logger previously had the name created asctrl.Log.WithName("controllers").WithName("AzureMachine"). Is this okay to change now? Same for other controllers as well.

I would assume so, but it sounds like you are concerned about something specific. What concerns you about changing these?

are we loosing info on the namespace and the name of the object? I see logger.WithValues("namespace", req.Namespace, "azureMachine", req.Name) was removed

are we loosing info on the namespace and the name of the object? I see logger.WithValues("namespace", req.Namespace, "azureMachine", req.Name) was removed

Indeed, that was removed, but it was added back in the tele.KVP attributes that are passed into tele.StartSpanWithLogger, which adds them as values to the composite logger.

shysank · 2021-11-24T16:35:22Z

azure/scope/machine.go

@@ -437,18 +429,21 @@ func (m *MachineScope) SetFailureReason(v capierrors.MachineStatusError) {
 }

 // SetBootstrapConditions sets the AzureMachine BootstrapSucceeded condition based on the extension provisioning states.
-func (m *MachineScope) SetBootstrapConditions(provisioningState string, extensionName string) error {
+func (m *MachineScope) SetBootstrapConditions(ctx context.Context, provisioningState string, extensionName string) error {
+	_, log, done := tele.StartSpanWithLogger(ctx, "scope.MachineScope.SetBootstrapConditions")


General question on the approach: All logs are now written through the span logger which also creates spans for the functions they are called in. This means we have already added spans to functions which previously didn't have one, and in future, we'll be adding more if we want to add logs. Will this create a flurry of spans and make it harder to visualize the flow?

Creating the spans and adding them to the traces in my opinion actually makes it easier to understand what is happening. If someone would like to filter spans, they are able to in the visualization or in the span data. Without producing the spans, the data would then be lost. For example, in Jaeger, I can just not expand items in the tree below a given level if I want. However, if I need to dig deeper I can. If we omit deeper span information, there is no option to dig deeper.

Additionally, exporters would likely be configured to do stochastic tracing only selecting a percentage of traces or a subset based on some criteria.

Overall, I'd bias toward over instrumentation and giving folks the ability to reduce based on export criteria.

wdyt?

devigned · 2021-12-03T23:17:10Z

/retest

devigned · 2021-12-06T14:23:02Z

/test pull-cluster-api-provider-azure-e2e

api/v1beta1/azurecluster_webhook.go

CecileRobertMichon · 2021-12-07T19:08:34Z

Given the size of the PR and the number of lines that it touches, I'm going to let it merge since this week is pretty slow and it should allow us to optimize for minimum collisions with other in-flight PRs. Most comments have been addressed and since this is not adding any features or APIs we can adjust and correct if needed. @shysank feel free to complete your review when you get back so any outstanding comments/questions you have can be addressed.

/lgtm
/approve

k8s-ci-robot · 2021-12-07T19:08:59Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: CecileRobertMichon

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~~ [CecileRobertMichon]

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

CecileRobertMichon · 2021-12-07T20:02:09Z

/retest

k8s-ci-robot · 2021-12-07T21:27:24Z

@devigned: The following test failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
pull-cluster-api-provider-azure-apidiff	`1e97558`	link	false	`/test pull-cluster-api-provider-azure-apidiff`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

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/test-infra repository. I understand the commands that are listed here.

devigned · 2021-12-07T21:43:22Z

/test pull-cluster-api-provider-azure-e2e

looks like e2e timed out 2h

k8s-ci-robot requested review from cpanato and juan-lee October 29, 2021 19:40

k8s-ci-robot added area/provider/azure Issues or PRs related to azure provider sig/cluster-lifecycle Categorizes an issue or PR as relevant to SIG Cluster Lifecycle. labels Oct 29, 2021

devigned force-pushed the mc-logs branch from b3f0c02 to 488ace3 Compare October 29, 2021 19:42

mboersma reviewed Nov 1, 2021

View reviewed changes

k8s-ci-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Nov 4, 2021

devigned force-pushed the mc-logs branch from 488ace3 to c7dfa59 Compare November 19, 2021 18:53

k8s-ci-robot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Nov 19, 2021

devigned changed the title ~~make all logging consistent across the controller~~ make all logging consistent across the controllers Nov 19, 2021

devigned force-pushed the mc-logs branch 4 times, most recently from 54ee02c to c05c760 Compare November 19, 2021 21:07

devigned force-pushed the mc-logs branch from c05c760 to 98b8d3e Compare November 20, 2021 01:22

k8s-ci-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Nov 20, 2021

devigned force-pushed the mc-logs branch from 98b8d3e to e9350ae Compare November 22, 2021 15:19

k8s-ci-robot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Nov 22, 2021

CecileRobertMichon reviewed Nov 23, 2021

View reviewed changes

main.go Outdated Show resolved Hide resolved

CecileRobertMichon reviewed Nov 23, 2021

View reviewed changes

controllers/azurecluster_controller.go Outdated Show resolved Hide resolved

CecileRobertMichon reviewed Nov 23, 2021

View reviewed changes

controllers/azureidentity_controller.go Outdated Show resolved Hide resolved

shysank reviewed Nov 24, 2021

View reviewed changes

k8s-ci-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Nov 30, 2021

devigned force-pushed the mc-logs branch from e9350ae to 9826b8c Compare December 3, 2021 00:32

k8s-ci-robot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Dec 3, 2021

devigned force-pushed the mc-logs branch 2 times, most recently from a2a5a4b to cc11107 Compare December 3, 2021 20:54

make all logging consistent across the controllers

1e97558

devigned force-pushed the mc-logs branch from cc11107 to 1e97558 Compare December 3, 2021 21:09

CecileRobertMichon reviewed Dec 6, 2021

View reviewed changes

api/v1beta1/azurecluster_webhook.go Show resolved Hide resolved

k8s-ci-robot assigned CecileRobertMichon Dec 7, 2021

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Dec 7, 2021

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Dec 7, 2021

k8s-ci-robot merged commit 90653c1 into kubernetes-sigs:main Dec 7, 2021

k8s-ci-robot added this to the v1.1 milestone Dec 7, 2021

devigned deleted the mc-logs branch December 7, 2021 22:53

This was referenced Dec 8, 2021

Refactor async service to use an async reconciler interface and handle getting existing resources #1874

Merged

Make NAT Gateway reconcile/delete async #1865

Merged

Make publicips reconcile/delete async #1745

Closed

shysank mentioned this pull request Jan 5, 2022

Log messages not pointing to the correct line number #1827

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

make all logging consistent across the controllers #1812

make all logging consistent across the controllers #1812

devigned commented Oct 29, 2021 •

edited

Loading

nader-ziada commented Nov 1, 2021

mboersma Nov 1, 2021

devigned Nov 19, 2021

mboersma Nov 1, 2021 •

edited

Loading

devigned Nov 19, 2021

mboersma Dec 3, 2021

mboersma Nov 1, 2021

devigned Nov 19, 2021

devigned commented Nov 19, 2021 •

edited

Loading

devigned commented Nov 22, 2021

shysank Nov 24, 2021

devigned Dec 3, 2021

CecileRobertMichon Dec 6, 2021

devigned Dec 7, 2021

shysank Nov 24, 2021

devigned Dec 3, 2021

devigned commented Dec 3, 2021

devigned commented Dec 6, 2021

CecileRobertMichon commented Dec 7, 2021

k8s-ci-robot commented Dec 7, 2021

CecileRobertMichon commented Dec 7, 2021

k8s-ci-robot commented Dec 7, 2021 •

edited

Loading

devigned commented Dec 7, 2021 •

edited

Loading

make all logging consistent across the controllers #1812

make all logging consistent across the controllers #1812

Conversation

devigned commented Oct 29, 2021 • edited Loading

nader-ziada commented Nov 1, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mboersma Nov 1, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

devigned commented Nov 19, 2021 • edited Loading

devigned commented Nov 22, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

devigned commented Dec 3, 2021

devigned commented Dec 6, 2021

CecileRobertMichon commented Dec 7, 2021

k8s-ci-robot commented Dec 7, 2021

CecileRobertMichon commented Dec 7, 2021

k8s-ci-robot commented Dec 7, 2021 • edited Loading

devigned commented Dec 7, 2021 • edited Loading

devigned commented Oct 29, 2021 •

edited

Loading

mboersma Nov 1, 2021 •

edited

Loading

devigned commented Nov 19, 2021 •

edited

Loading

k8s-ci-robot commented Dec 7, 2021 •

edited

Loading

devigned commented Dec 7, 2021 •

edited

Loading