(continuation) Enable logs from chain elements regardless of EnableTr…

…acing (#1489) * make IsTracingEnabled independent from log level Signed-off-by: Danil Uzlov <DanilUzlov@yandex.ru> always inject logger into context Signed-off-by: Danil Uzlov <DanilUzlov@yandex.ru> fix copyright Signed-off-by: Danil Uzlov <DanilUzlov@yandex.ru> fix race condition Signed-off-by: Danil Uzlov <DanilUzlov@yandex.ru> * Add fixes for registry, dns Signed-off-by: Artem Glazychev <artem.glazychev@xored.com> --------- Signed-off-by: Danil Uzlov <DanilUzlov@yandex.ru> Signed-off-by: Artem Glazychev <artem.glazychev@xored.com> Co-authored-by: Danil Uzlov <DanilUzlov@yandex.ru>
networkservicemesh · Jul 13, 2023 · eaf1d25 · eaf1d25
1 parent 01bb35f
commit eaf1d25
Show file tree

Hide file tree

Showing 7 changed files with 87 additions and 44 deletions.
diff --git a/pkg/networkservice/core/trace/context.go b/pkg/networkservice/core/trace/context.go
@@ -54,18 +54,21 @@ func withLog(parent context.Context, operation, methodName, connectionID string)
 	// Update outgoing grpc context
 	parent = grpcutils.PassTraceToOutgoing(parent)
 
+	fields := []*log.Field{log.NewField("id", connectionID), log.NewField("type", loggedType)}
+
+	ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, methodName, fields)
+	ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, fields)
+
+	ctx = log.WithLog(ctx, sLogger, lLogger)
+
 	if grpcTraceState := grpcutils.TraceFromContext(parent); (grpcTraceState == grpcutils.TraceOn) ||
 		(grpcTraceState == grpcutils.TraceUndefined && log.IsTracingEnabled()) {
-		fields := []*log.Field{log.NewField("id", connectionID), log.NewField("type", loggedType)}
-
-		ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, methodName, fields)
-		ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, fields)
-		return withTrace(log.WithLog(ctx, sLogger, lLogger)), func() {
-			sFinish()
-			lFinish()
-		}
+		ctx = withTrace(ctx)
+	}
+	return ctx, func() {
+		sFinish()
+		lFinish()
 	}
-	return log.WithLog(parent), func() {}
 }
 
 // withConnectionInfo - Provides a traceInfo in context
@@ -81,7 +84,7 @@ func withTrace(parent context.Context) context.Context {
 	return context.WithValue(parent, traceInfoKey, &traceInfo{})
 }
 
-// ConnectionInfo - return traceInfo from context
+// trace - return traceInfo from context
 func trace(ctx context.Context) (*traceInfo, bool) {
 	val, ok := ctx.Value(traceInfoKey).(*traceInfo)
 	return val, ok

diff --git a/pkg/registry/common/authorize/common.go b/pkg/registry/common/authorize/common.go
@@ -60,8 +60,6 @@ func (l *policiesList) check(ctx context.Context, input RegistryOpaInput) error
 			log.FromContext(ctx).Errorf("policy failed: %v", policy.Name())
 			return errors.Wrap(err, "registry: an error occurred during authorization policy check")
 		}
-
-		log.FromContext(ctx).Infof("policy passed")
 	}
 	return nil
 }

diff --git a/pkg/registry/core/trace/common.go b/pkg/registry/core/trace/common.go
@@ -54,6 +54,10 @@ func logError(ctx context.Context, err error, operation string) error {
 }
 
 func logObjectTrace(ctx context.Context, k, v interface{}) {
+	if ok := trace(ctx); !ok {
+		return
+	}
+
 	s := log.FromContext(ctx)
 	msg := ""
 	cc, err := json.Marshal(v)

diff --git a/pkg/registry/core/trace/context.go b/pkg/registry/core/trace/context.go
@@ -27,10 +27,16 @@ import (
 	"github.com/networkservicemesh/sdk/pkg/tools/log/spanlogger"
 )
 
+type contextKeyType string
+
 const (
-	loggedType = "registry"
+	traceInfoKey contextKeyType = "ConnectionInfoRegistry"
+	loggedType   string         = "registry"
 )
 
+// ConnectionInfo - struct is used for tracing.
+type traceInfo struct{}
+
 // withLog - provides corresponding logger in context
 func withLog(parent context.Context, operation, methodName string) (c context.Context, f func()) {
 	if parent == nil {
@@ -40,16 +46,38 @@ func withLog(parent context.Context, operation, methodName string) (c context.Co
 	// Update outgoing grpc context
 	parent = grpcutils.PassTraceToOutgoing(parent)
 
+	fields := []*log.Field{log.NewField("type", loggedType)}
+
+	ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, methodName, fields)
+	ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, fields)
+
+	ctx = log.WithLog(ctx, sLogger, lLogger)
+
 	if grpcTraceState := grpcutils.TraceFromContext(parent); (grpcTraceState == grpcutils.TraceOn) ||
 		(grpcTraceState == grpcutils.TraceUndefined && log.IsTracingEnabled()) {
-		fields := []*log.Field{log.NewField("type", loggedType)}
-
-		ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, methodName, fields)
-		ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, fields)
-		return log.WithLog(ctx, sLogger, lLogger), func() {
-			sFinish()
-			lFinish()
-		}
+		ctx = withTrace(ctx)
+	}
+	return ctx, func() {
+		sFinish()
+		lFinish()
 	}
-	return log.WithLog(parent), func() {}
+}
+
+// withConnectionInfo - Provides a traceInfo in context
+func withTrace(parent context.Context) context.Context {
+	if parent == nil {
+		panic("cannot create context from nil parent")
+	}
+	if ok := trace(parent); ok {
+		// We already had connection info
+		return parent
+	}
+
+	return context.WithValue(parent, traceInfoKey, &traceInfo{})
+}
+
+// trace - return traceInfo from context
+func trace(ctx context.Context) bool {
+	_, ok := ctx.Value(traceInfoKey).(*traceInfo)
+	return ok
 }
diff --git a/pkg/tools/dnsutils/trace/context.go b/pkg/tools/dnsutils/trace/context.go
@@ -44,17 +44,20 @@ func withLog(parent context.Context, operation, methodName, messageID string) (c
 		panic("cannot create context from nil parent")
 	}
 
-	if log.IsTracingEnabled() {
-		fields := []*log.Field{log.NewField("type", loggedType), log.NewField("id", messageID)}
+	fields := []*log.Field{log.NewField("type", loggedType), log.NewField("id", messageID)}
+
+	ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, methodName, fields)
+	ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, fields)
+
+	ctx = log.WithLog(ctx, sLogger, lLogger)
 
-		ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, methodName, fields)
-		ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, fields)
-		return withTrace(log.WithLog(ctx, sLogger, lLogger)), func() {
-			sFinish()
-			lFinish()
-		}
+	if log.IsTracingEnabled() {
+		ctx = withTrace(ctx)
+	}
+	return ctx, func() {
+		sFinish()
+		lFinish()
 	}
-	return log.WithLog(parent), func() {}
 }
 
 func withTrace(parent context.Context) context.Context {

diff --git a/pkg/tools/log/logger.go b/pkg/tools/log/logger.go
@@ -1,5 +1,7 @@
 // Copyright (c) 2021-2022 Doc.ai and/or its affiliates.
 //
+// Copyright (c) 2023 Cisco Systems, Inc.
+//
 // SPDX-License-Identifier: Apache-2.0
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
@@ -20,8 +22,6 @@ package log
 import (
 	"context"
 	"sync/atomic"
-
-	"github.com/sirupsen/logrus"
 )
 
 type contextKeyType string
@@ -92,7 +92,7 @@ func WithLog(ctx context.Context, log ...Logger) context.Context {
 // IsTracingEnabled - checks if it is allowed to use traces
 func IsTracingEnabled() bool {
 	// TODO: Rework this within https://github.com/networkservicemesh/sdk/issues/1272
-	return atomic.LoadInt32(&isTracingEnabled) != 0 && logrus.GetLevel() == logrus.TraceLevel
+	return atomic.LoadInt32(&isTracingEnabled) != 0
 }
 
 // EnableTracing - enable/disable traces

diff --git a/pkg/tools/log/logruslogger/logruslogger.go b/pkg/tools/log/logruslogger/logruslogger.go
@@ -29,6 +29,7 @@ import (
 
 	"github.com/google/uuid"
 	"github.com/sirupsen/logrus"
+	"go.uber.org/atomic"
 	"google.golang.org/grpc/metadata"
 
 	"github.com/networkservicemesh/sdk/pkg/tools/log"
@@ -139,7 +140,7 @@ var localTraceInfo sync.Map
 
 type traceCtxInfo struct {
 	level      int
-	childCount int
+	childCount atomic.Int32
 	id         string
 }
 
@@ -214,17 +215,17 @@ func (s *traceLogger) WithField(key, value interface{}) log.Logger {
 }
 
 func (i *traceCtxInfo) incInfo() string {
-	i.childCount++
-	if i.childCount > 1 {
-		return fmt.Sprintf("(%d.%d)", i.level, i.childCount-1)
+	newValue := i.childCount.Inc()
+	if newValue > 1 {
+		return fmt.Sprintf("(%d.%d)", i.level, newValue-1)
 	}
 	return fmt.Sprintf("(%d)", i.level)
 }
 
 func withTraceInfo(parent context.Context) (context.Context, *traceCtxInfo) {
 	newInfo := &traceCtxInfo{
 		level:      1,
-		childCount: 0,
+		childCount: atomic.Int32{},
 		id:         uuid.New().String(),
 	}
 
@@ -275,8 +276,12 @@ func (s *traceLogger) getTraceInfo() string {
 func FromSpan(
 	ctx context.Context, span spanlogger.Span, operation string, fields []*log.Field) (context.Context, log.Logger, func()) {
 	var info *traceCtxInfo
-	ctx, info = withTraceInfo(ctx)
-	localTraceInfo.Store(info.id, info)
+	deleteFunc := func() {}
+	if log.IsTracingEnabled() {
+		ctx, info = withTraceInfo(ctx)
+		localTraceInfo.Store(info.id, info)
+		deleteFunc = func() { localTraceInfo.Delete(info.id) }
+	}
 
 	logger := log.L()
 	if log.IsDefault(logger) {
@@ -303,12 +308,14 @@ func FromSpan(
 	}
 
 	newLog.printStart()
-	return ctx, newLog, func() { localTraceInfo.Delete(info.id) }
+	return ctx, newLog, deleteFunc
 }
 
 func (s *traceLogger) printStart() {
-	prefix := strings.Repeat(separator, s.info.level)
-	s.logger.Tracef("%v%s⎆ %v()%v", s.info.incInfo(), prefix, s.operation, s.getSpan())
+	if s.info != nil {
+		prefix := strings.Repeat(separator, s.info.level)
+		s.logger.Tracef("%v%s⎆ %v()%v", s.info.incInfo(), prefix, s.operation, s.getSpan())
+	}
 }
 
 func (s *traceLogger) format(format string, v ...interface{}) string {