ETW logging implementation in CNI (#2668)

* Add ETW support in zap logger for CNI

Added a zap WriteSyncer to enable direct ETW logging through zap core, maintaining existing logging structure while to ETW from CNI.

* Transform 'zapetw' package into a standalone module for external use

* Revert "Transform 'zapetw' package into a standalone module for external use"

This reverts commit 63050ed68d353e43ae1b1fedd11b8e99259b7a28.

* Relocate EtwWriteSyncer.go to zapetw module for improved organization

- Renamed and moved cni/log/ETWZapCore/EtwWriteSyncer.go to zapetw/write_syncer.go.

* Applied gofumpt formatting to adhere to style guidelines.

* 1. Implemented platform-specific ETW logging enhancements.
2. Refactor ETW initialization into dedicated method and zapetw package.

* Changed InitETWLogger method signature for Linux.

* Wrapped error messages at each level of the call hierarchy.

* Removed punctuation marks from error messages.

* Wrapped error messages with errors.wrap method.

* Added comments for clarity.

* implemented zap.core for ETW.

* Fixed lint issues.

* Catch errors from etw.writeEvent method.

* Renamed provider.

* Abstracted etw core creation in logger_windows.
Removed unsupported error from logger_linux to keep the behaviour uniform.

* renamed unused parameter.

* Renamed variable to lower camel case as it is private. Removed additional local reference.

* fixed variable name.

* Added comment.

* Renamed ETW provider, removed application names from the provider name.

---------

Co-authored-by: Sivakami Subramaniam <t-sivakamis@microsoft.com>

cni/log/logger.go

@@ -17,6 +17,8 @@ var (
 const (
 	maxLogFileSizeInMb = 5
 	maxLogFileCount    = 8
+	etwCNIEventName    = "Azure-CNI"
+	loggingLevel       = zapcore.DebugLevel
 )
 
 func initZapLog(logFile string) *zap.Logger {
@@ -30,13 +32,17 @@ func initZapLog(logFile string) *zap.Logger {
 	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
 	jsonEncoder := zapcore.NewJSONEncoder(encoderConfig)
 
-	core := zapcore.NewCore(jsonEncoder, logFileCNIWriter, zapcore.DebugLevel)
+	textFileCore := zapcore.NewCore(jsonEncoder, logFileCNIWriter, loggingLevel)
-	Logger := zap.New(core)
+	core, err := JoinPlatformCores(textFileCore, loggingLevel)
-	return Logger
+	if err != nil {
+		// If we fail to join the platform cores, fallback to the original core.
+		core = textFileCore
+	}
+	return zap.New(core, zap.AddCaller()).With(zap.Int("pid", os.Getpid()))
 }
 
 var (
-	CNILogger       = initZapLog(zapCNILogFile).With(zap.Int("pid", os.Getpid()))
+	CNILogger       = initZapLog(zapCNILogFile)
-	IPamLogger      = initZapLog(zapIpamLogFile).With(zap.Int("pid", os.Getpid()))
+	IPamLogger      = initZapLog(zapIpamLogFile)
-	TelemetryLogger = initZapLog(zapTelemetryLogFile).With(zap.Int("pid", os.Getpid()))
+	TelemetryLogger = initZapLog(zapTelemetryLogFile)
 )

cni/log/logger_linux.go

@@ -1,6 +1,14 @@
 package log
 
+import (
+	"go.uber.org/zap/zapcore"
+)
+
 const (
 	// LogPath is the path where log files are stored.
 	LogPath = "/var/log/"
 )
+
+func JoinPlatformCores(c zapcore.Core, _ zapcore.Level) (zapcore.Core, error) {
+	return c, nil
+}

cni/log/logger_windows.go

@@ -1,6 +1,34 @@
 package log
 
+import (
+	"github.com/Azure/azure-container-networking/zapetw"
+	"github.com/pkg/errors"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
 const (
 	// LogPath is the path where log files are stored.
 	LogPath = ""
 )
+
+func JoinPlatformCores(core zapcore.Core, loggingLevel zapcore.Level) (zapcore.Core, error) {
+	etwcore, err := etwCore(loggingLevel)
+	if err != nil {
+		return core, err
+	}
+	teecore := zapcore.NewTee(core, etwcore)
+	return teecore, nil
+}
+
+func etwCore(loggingLevel zapcore.Level) (zapcore.Core, error) {
+	encoderConfig := zap.NewProductionEncoderConfig()
+	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
+	jsonEncoder := zapcore.NewJSONEncoder(encoderConfig)
+
+	etwcore, err := zapetw.NewETWCore(etwCNIEventName, jsonEncoder, loggingLevel)
+	if err != nil {
+		return nil, errors.Wrap(err, "failed to create ETW core")
+	}
+	return etwcore, nil
+}

zapetw/core_windows.go

@@ -0,0 +1,92 @@
+package zapetw
+
+import (
+	"github.com/Microsoft/go-winio/pkg/etw"
+	"github.com/pkg/errors"
+	"go.uber.org/zap/zapcore"
+)
+
+// <product_name>-<component_name>
+const providername = "ACN-Monitoring"
+
+type ETWCore struct {
+	provider  *etw.Provider
+	eventName string
+	encoder   zapcore.Encoder
+	fields    []zapcore.Field
+	zapcore.LevelEnabler
+}
+
+func NewETWCore(eventName string, encoder zapcore.Encoder, levelEnabler zapcore.LevelEnabler) (*ETWCore, error) {
+	provider, err := etw.NewProviderWithOptions(providername)
+	if err != nil {
+		return nil, errors.Wrap(err, "failed to create ETW provider")
+	}
+	return &ETWCore{
+		provider:     provider,
+		eventName:    eventName,
+		encoder:      encoder,
+		LevelEnabler: levelEnabler,
+	}, nil
+}
+
+func (core *ETWCore) With(fields []zapcore.Field) zapcore.Core {
+	return &ETWCore{
+		provider:     core.provider,
+		eventName:    core.eventName,
+		encoder:      core.encoder,
+		LevelEnabler: core.LevelEnabler,
+		fields:       append(core.fields, fields...),
+	}
+}
+
+// Check is an implementation of the zapcore.Core interface's Check method.
+// Check determines whether the logger core is enabled at the supplied zapcore.Entry's Level.
+// If enabled, it adds the core to the CheckedEntry and returns it, otherwise returns the CheckedEntry unchanged.
+func (core *ETWCore) Check(entry zapcore.Entry, checkedEntry *zapcore.CheckedEntry) *zapcore.CheckedEntry {
+	if core.Enabled(entry.Level) {
+		return checkedEntry.AddCore(entry, core)
+	}
+	return checkedEntry
+}
+
+func (core *ETWCore) Write(entry zapcore.Entry, fields []zapcore.Field) error {
+	etwLevel := zapLevelToETWLevel(entry.Level)
+
+	buffer, err := core.encoder.EncodeEntry(entry, fields)
+	if err != nil {
+		return errors.Wrap(err, "failed to encode entry")
+	}
+
+	err = core.provider.WriteEvent(
+		core.eventName,
+		[]etw.EventOpt{etw.WithLevel(etwLevel)},
+		[]etw.FieldOpt{etw.StringField("Message", buffer.String())},
+	)
+	if err != nil {
+		return errors.Wrap(err, "failed to write event")
+	}
+
+	return nil
+}
+
+func (core *ETWCore) Sync() error {
+	return nil
+}
+
+func zapLevelToETWLevel(level zapcore.Level) etw.Level {
+	switch level {
+	case zapcore.DebugLevel:
+		return etw.LevelVerbose // ETW doesn't have a Debug level, so Verbose is used instead.
+	case zapcore.InfoLevel:
+		return etw.LevelInfo
+	case zapcore.WarnLevel:
+		return etw.LevelWarning
+	case zapcore.ErrorLevel:
+		return etw.LevelError
+	case zapcore.DPanicLevel, zapcore.PanicLevel, zapcore.FatalLevel, zapcore.InvalidLevel:
+		return etw.LevelCritical
+	default:
+		return etw.LevelAlways
+	}
+}