feat: refactor cni telemetry #3149

QxBytes · 2024-11-14T19:37:18Z

Reason for Change:

Currently the telemetry CNI is sending is insufficient to debug CNI issues. This PR refactors the cni telemetry to send more and better quality logs.

Moves telemetry into a package level variable so it is made accessible everywhere
Removes sending certain metrics as they are not used
Sets the subcontext to the container id. The container id is kept consistent throughout CNI calls for the same pod, meaning an ADD and DEL call (and all related logs) for the same pod will have the same subcontext/container id. The container id is also what is stored in stateless mode as one of the keys.
Sets the operation id before any telemetry events are sent. The operation id is used for sampling should we end up enabling it.

Examples of Logged information (Will be added in a separate PR-- this PR is focused on refactoring)

CNI add network configuration, arguments
CNI add completion with endpoint info struct information (contains hns endpoint id and hns network id), interface results from the ipam invoker, and any error that occurred
CNI del network configuration, arguments
CNI del completion with error that occurred
HNS Endpoint struct before creation / HNS Endpoint Id during deletion
HNS Network struct before creation / HNS Network Id during deletion
Deletion/Release of each IP (even if does not exist)
Mapping sent to CNS during stateless CNI mode during Update Endpoint State
Exact CNS response from CNS ipam invoker
Exact CNS response from multitenancy ipam invoker
Transparent vlan creating/deleting vlan veth interface

Potential additions:

endpoint and network structs saved to azure-vnet.json statefile

Issue Fixed:

Requirements:

uses conventional commit messages
includes documentation
adds unit tests
relevant PR labels added

Notes:
Pipeline run to prove logs sent to kusto: https://msazure.visualstudio.com/One/_build/results?buildId=108208651&view=results
Passing run: https://msazure.visualstudio.com/One/_build/results?buildId=108563465&view=results

ramiro-gamarra · 2024-11-15T20:33:41Z

cni/telemetry/client/telemetry_client.go

+
+func (c *TelemetryClient) SendEvent(msg string) {
+	c.sendLog(msg)
+	c.sendTelemetry(msg)


what is the difference between log and telemetry here?

logs are sent to azure-vnet.log. Telemetry is sent to the telemetry service on the node which then sends it to application insights.

ramiro-gamarra · 2024-11-15T20:39:00Z

cni/telemetry/client/telemetry_client.go

+	}
+}
+
+func (c *TelemetryClient) ConnectTelemetry(logger *zap.Logger) {


why can't this be part of the constructor? wouldn't that remove the need for nil checks?

If we ConnectTelemetry in NewTelemetryClient I believe we would try to connect to the telemetry service during tests, which I do not want to occur. Connect / StartAndConnect are also called by different main methods (stateless vs. non-stateless cni) whereas NewTelemetryClient is called for both. Adding attempts to only connect to NewTelemetryClient (via ConnectTelemetry) would be incorrect behavior in non-stateless cni because we want to start the telemetry service before any connection is attempted.

QxBytes · 2024-11-15T21:24:15Z

/azp run Azure Container Networking PR

azure-pipelines · 2024-11-15T21:24:28Z

Azure Pipelines successfully started running 1 pipeline(s).

we will split this part of the pr into its own pr a telemetry event was added back which was previously removed undo this pr to add those telemetry statements back

cni/network/plugin/main.go

cni/network/stateless/main.go

remove reflect remove duplicated telemetry and telemetry buffer remove unused fields in report manager force access to telemetry client fields through methods move telemetry start/connect code closer to start of plugin execution

we use SendError where we would have previously called reportPluginError (no log emitted) we don't set error message in cni report because the error message and event message fields both end up in the Message field in the cni telemetry service

timraymond · 2024-11-19T18:04:34Z

LGTM on @ramiro-gamarra 's approval

ramiro-gamarra · 2024-11-19T19:15:51Z

cni/network/network.go

@@ -479,18 +436,12 @@ func (plugin *NetPlugin) Add(args *cniSkel.CmdArgs) error {
 			zap.String("pod", k8sPodName),
 			zap.Any("IPs", cniResult.IPs),
 			zap.Error(log.NewErrorWithoutStackTrace(err)))
+
+		telemetry.SendEvent(fmt.Sprintf("ADD command completed with [ipamAddResult]: %s [epInfos]: %s [error]: %v ", ipamAddResult.PrettyString(), network.FormatStructPointers(epInfos), err))


Per one of your previous comments, telemetry.SendEvent will both write to azure-vnet.log as well as send to telemetry service. Aren't we then writing to the log file twice here if logger also writes to the file? Can we keep this PR to only a pure refactor without introducing new side effects?

yes you are correct, I've removed the duplicate logger statement in the telemetry client

cni/network/network.go

ramiro-gamarra · 2024-11-19T19:17:56Z

cni/network/network.go


 	defer func() {
 		logger.Info("DEL command completed",
 			zap.String("pod", k8sPodName),
 			zap.Error(log.NewErrorWithoutStackTrace(err)))
+		telemetry.SendEvent(fmt.Sprintf("DEL command completed: [released ip]: %+v [podname]: %s [namespace]: %s [error]: %v", nwCfg.IPAM.Address, k8sPodName, k8sNamespace, err))


same as above. if logger already writes to the file, then we are just duplicating data, as well as going away from structured logs.

addressed above-- I was trying to replicate what I was seeing in the cnslogger but since we log before anyway this isn't helpful

ramiro-gamarra

I may still be missing some details about the purpose of this refactor, but seems to me that logs are getting duplicated and the abstractions introduced are not cleaning up the code much yet.

ramiro-gamarra · 2024-11-19T19:24:57Z

cni/telemetry/client/telemetry_client.go

+	telemetryWaitTimeInMilliseconds = 200
+)
+
+type TelemetryClient struct {


There's a lot of stutter in the naming. Can't there just be a telemetry package with a Client type?

moved the telemetry client to the existing telemetry package

ramiro-gamarra · 2024-11-19T19:25:57Z

cni/telemetry/client/telemetry_client.go

+	lock              sync.Mutex
+}
+
+type TelemetryInterface interface {


There's only a single implementation of this interface. This is not needed.

ramiro-gamarra · 2024-11-19T19:27:12Z

cni/telemetry/client/telemetry_client.go

+	cniReportSettings *telemetry.CNIReport
+	tb                *telemetry.TelemetryBuffer
+	logger            *zap.Logger
+	lock              sync.Mutex


is CNI spinning goroutines? What is this lock serializing?

currently we don't send telemetry from multiple goroutines as far as I can tell, but if we want to send telemetry from anywhere in the codebase in the future, I would prefer to serialize this and not worry about races etc. later, but I can remove the lock for now if you would like.

QxBytes added 5 commits November 7, 2024 10:30

move telemetry to dedicated package and create package variable

8046c63

send telemetry for ipam config, epinfo, and error on cni add completion

0451318

add new telemetry logs for debugging

77de27f

replace nwcfg subcontext with containerid for correlation

fd76e5a

add mutex

d341612

QxBytes changed the title ~~ci: refactor cni telemetry~~ feat: refactor cni telemetry Nov 14, 2024

QxBytes self-assigned this Nov 14, 2024

QxBytes added cni Related to CNI. ci Infra or tooling. telemetry logging labels Nov 14, 2024

address linter issues

0613803

QxBytes force-pushed the alew/refactor-telemetry branch from 23e8b82 to 0613803 Compare November 14, 2024 20:18

add unit tests

c016472

QxBytes marked this pull request as ready for review November 14, 2024 23:56

QxBytes requested review from a team as code owners November 14, 2024 23:56

QxBytes requested a review from jpayne3506 November 14, 2024 23:56

ramiro-gamarra reviewed Nov 15, 2024

View reviewed changes

set operation id before sending any events for sampling

519c293

QxBytes force-pushed the alew/refactor-telemetry branch from 0ea0ad4 to b956ec4 Compare November 15, 2024 21:26

remove newly added telemetry events

dd9ca83

we will split this part of the pr into its own pr a telemetry event was added back which was previously removed undo this pr to add those telemetry statements back

QxBytes force-pushed the alew/refactor-telemetry branch from b956ec4 to dd9ca83 Compare November 15, 2024 21:31

timraymond reviewed Nov 18, 2024

View reviewed changes

cni/network/plugin/main.go Outdated Show resolved Hide resolved

cni/network/stateless/main.go Outdated Show resolved Hide resolved

QxBytes added 3 commits November 18, 2024 11:50

refactor plugin main

787eaef

remove reflect remove duplicated telemetry and telemetry buffer remove unused fields in report manager force access to telemetry client fields through methods move telemetry start/connect code closer to start of plugin execution

add unit tests and simplify

73bd871

we use SendError where we would have previously called reportPluginError (no log emitted) we don't set error message in cni report because the error message and event message fields both end up in the Message field in the cni telemetry service

remove duplicate error telemetry

094bbc9

QxBytes requested a review from timraymond November 19, 2024 00:31

QxBytes requested a review from ramiro-gamarra November 19, 2024 00:31

fix comment

9daf6d3

ramiro-gamarra reviewed Nov 19, 2024

View reviewed changes

cni/network/network.go Show resolved Hide resolved

ramiro-gamarra reviewed Nov 19, 2024

View reviewed changes

remove writing telemetry events to the log file

c783032

ramiro-gamarra requested changes Nov 19, 2024

View reviewed changes

QxBytes added 2 commits November 19, 2024 12:00

address feedback

27832a1

remove stutter

846ed20

QxBytes requested a review from ramiro-gamarra November 19, 2024 22:02

remove unused map (noop)

8c83456

QxBytes requested a review from behzad-mir November 22, 2024 00:25

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: refactor cni telemetry #3149

feat: refactor cni telemetry #3149

QxBytes commented Nov 14, 2024 •

edited

Loading

ramiro-gamarra Nov 15, 2024

QxBytes Nov 15, 2024

ramiro-gamarra Nov 15, 2024

QxBytes Nov 15, 2024

QxBytes commented Nov 15, 2024

azure-pipelines bot commented Nov 15, 2024

timraymond commented Nov 19, 2024

ramiro-gamarra Nov 19, 2024

QxBytes Nov 19, 2024

ramiro-gamarra Nov 19, 2024

QxBytes Nov 19, 2024 •

edited

Loading

ramiro-gamarra left a comment

ramiro-gamarra Nov 19, 2024

QxBytes Nov 19, 2024

ramiro-gamarra Nov 19, 2024

ramiro-gamarra Nov 19, 2024

QxBytes Nov 19, 2024

feat: refactor cni telemetry #3149

Are you sure you want to change the base?

feat: refactor cni telemetry #3149

Conversation

QxBytes commented Nov 14, 2024 • 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

QxBytes commented Nov 15, 2024

azure-pipelines bot commented Nov 15, 2024

timraymond commented Nov 19, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

QxBytes Nov 19, 2024 • edited Loading

Choose a reason for hiding this comment

ramiro-gamarra left a 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

Choose a reason for hiding this comment

QxBytes commented Nov 14, 2024 •

edited

Loading

QxBytes Nov 19, 2024 •

edited

Loading