From eaf1d25c751245a1a9832755c7b5b3129ab08d6f Mon Sep 17 00:00:00 2001 From: Artem Glazychev Date: Thu, 13 Jul 2023 15:43:22 +0700 Subject: [PATCH] (continuation) Enable logs from chain elements regardless of EnableTracing (#1489) * make IsTracingEnabled independent from log level Signed-off-by: Danil Uzlov always inject logger into context Signed-off-by: Danil Uzlov fix copyright Signed-off-by: Danil Uzlov fix race condition Signed-off-by: Danil Uzlov * Add fixes for registry, dns Signed-off-by: Artem Glazychev --------- Signed-off-by: Danil Uzlov Signed-off-by: Artem Glazychev Co-authored-by: Danil Uzlov --- pkg/networkservice/core/trace/context.go | 23 ++++++----- pkg/registry/common/authorize/common.go | 2 - pkg/registry/core/trace/common.go | 4 ++ pkg/registry/core/trace/context.go | 48 +++++++++++++++++----- pkg/tools/dnsutils/trace/context.go | 21 ++++++---- pkg/tools/log/logger.go | 6 +-- pkg/tools/log/logruslogger/logruslogger.go | 27 +++++++----- 7 files changed, 87 insertions(+), 44 deletions(-) diff --git a/pkg/networkservice/core/trace/context.go b/pkg/networkservice/core/trace/context.go index 307f55026..c60d35755 100644 --- 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 index de54bf027..b0aca2086 100644 --- 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 index 6af03d9f9..d0eafd91d 100644 --- 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 index ac09d9a21..47ef2f1f5 100644 --- 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 index 197576f01..ba1912c48 100644 --- 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 index fbeeb1966..157f5eab2 100644 --- 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 index d66848fc7..3e8e4b840 100644 --- 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,9 +215,9 @@ 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) } @@ -224,7 +225,7 @@ func (i *traceCtxInfo) incInfo() string { 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 {