Fix to prevent data races #422

Mixaster995 · 2021-11-22T09:07:34Z

Signed-off-by: Mikhail Avramenko avramenkomihail15@gmail.com

Description

Removed unnecessary fields from context to prevent data races in logs.

Issue

fixes #419

denis-tingaikin · 2021-11-22T11:03:33Z

internal/manager/manager.go

@@ -96,7 +96,6 @@ func RunNsmgr(ctx context.Context, configuration *config.Config) error {

 	// Context to use for all things started in main
 	m.ctx, m.cancelFunc = context.WithCancel(ctx)
-	m.ctx = log.WithFields(m.ctx, map[string]interface{}{"cmd": "Nsmgr"})


I think this is needed for https://github.com/networkservicemesh/cmd-nsmgr/blob/main/internal/manager/manager.go#L164

Please consider using separate contexts for chain nsmgr and for logging in RunNsmgr

denis-tingaikin · 2021-11-22T12:10:07Z

internal/manager/manager.go

-	m.ctx = log.WithFields(m.ctx, map[string]interface{}{"cmd": "Nsmgr"})
-	m.ctx = log.WithLog(m.ctx, logruslogger.New(m.ctx))
+	logCtx := log.WithLog(m.ctx, logruslogger.New(m.ctx))
+	logCtx = log.WithFields(logCtx, map[string]interface{}{"cmd": "Nsmgr"})


logger = logruslogger.New(m.ctx)

logger...

TODO1: add spanlogger
TODO2: use the logger in each place where we are logging in this code file. (remove all direct logrus using)

ok, removed logrus, added separate context with spanlogger

edwarnicke · 2021-11-23T04:03:41Z

Why does trace need its on context?

Mixaster995 · 2021-11-23T08:33:19Z

@edwarnicke you right, it is unnecessary, added some refactoring

denis-tingaikin · 2021-11-23T09:59:45Z

main.go

+	traceCtx := log.WithFields(ctx, map[string]interface{}{"cmd": os.Args[:1]})
+	traceLogger, finish := utils.GetTraceLogger(traceCtx, "nsmgr")


Suggested change

traceCtx := log.WithFields(ctx, map[string]interface{}{"cmd": os.Args[:1]})

traceLogger, finish := utils.GetTraceLogger(traceCtx, "nsmgr")

_, sLogger, _, sFinish := spanlogger.FromContext(ctx, "cmd-nsmgr")

defer sFinish()

_ , lLogger, lFinish := logruslogger.FromSpan(ctx, span, "cmd-nsmgr")

defer lFinish()

logger := log.New(sLogger, lLogger)

Note: I think we need to expose group func from sdk

@denis-tingaikin should i prepare separate PR to sdk for this?

@Mixaster995 yes

denis-tingaikin · 2021-11-23T10:00:17Z

main.go


 	// ********************************************************************************
 	// Debug self if necessary
 	// ********************************************************************************
 	if err := debug.Self(); err != nil {
-		log.FromContext(ctx).Infof("%s", err)
+		traceLogger.Infof("%s", err)


Suggested change

traceLogger.Infof("%s", err)

logger.Infof("%s", err)

denis-tingaikin · 2021-11-23T10:00:38Z

main.go

 	}

 	// ********************************************************************************
 	// Configure open tracing
 	// ********************************************************************************
 	// Enable Jaeger
 	log.EnableTracing(true)
-	jaegerCloser := jaeger.InitJaeger(ctx, "nsmgr")
+	jaegerCloser := jaeger.InitJaeger(traceCtx, "nsmgr")


Suggested change

jaegerCloser := jaeger.InitJaeger(traceCtx, "nsmgr")

jaegerCloser := jaeger.InitJaeger(ctx, "nsmgr")

denis-tingaikin · 2021-11-23T10:00:49Z

main.go


 	// Get cfg from environment
 	cfg := &config.Config{}
 	if err := envconfig.Usage("nsm", cfg); err != nil {
-		logrus.Fatal(err)
+		traceLogger.Fatal(err)


Suggested change

traceLogger.Fatal(err)

logger.Fatal(err)

denis-tingaikin · 2021-11-23T10:00:56Z

main.go

 	}
 	if err := envconfig.Process("nsm", cfg); err != nil {
-		logrus.Fatalf("error processing cfg from env: %+v", err)
+		traceLogger.Fatalf("error processing cfg from env: %+v", err)


Suggested change

traceLogger.Fatalf("error processing cfg from env: %+v", err)

logger.Fatalf("error processing cfg from env: %+v", err)

denis-tingaikin · 2021-11-23T10:06:21Z

internal/manager/manager.go

 	m := &manager{
 		configuration: configuration,
+		traceLogger:   traceLogger,


Suggested change

traceLogger: traceLogger,

logger: logger,

denis-tingaikin · 2021-11-23T10:06:36Z

internal/manager/manager.go

@@ -87,20 +87,21 @@ func (m *manager) initSecurity() (err error) {
 func RunNsmgr(ctx context.Context, configuration *config.Config) error {


Suggested change

func RunNsmgr(ctx context.Context, configuration *config.Config) error {

func RunNsmgr(ctx context.Context, logger log.Logger, configuration *config.Config) error {

denis-tingaikin · 2021-11-23T10:06:41Z

internal/manager/manager.go

@@ -54,6 +53,7 @@ const (

 type manager struct {
 	ctx           context.Context
+	traceLogger   log.Logger


Suggested change

traceLogger log.Logger

logger log.Logger

denis-tingaikin · 2021-11-23T10:07:31Z

internal/manager/manager.go

@@ -54,6 +53,7 @@ const (

 type manager struct {


I would be suggested to remove this package. And use all this code inline. This can be done in separate PR.
@edwarnicke Thoughts?

In the generic I agree... not sure whether its necessary before the release or not though. How much work would it be and how much risk would it entail?

I think you're correct. Let's consider this after release.

denis-tingaikin · 2021-11-23T10:07:48Z

main.go

-	return log.WithLog(ctx, sLogger, lLogger), func() {
-		sFinish()
-		lFinish()
+		traceLogger.Fatalf("error executing rootCmd: %v", err)


Suggested change

traceLogger.Fatalf("error executing rootCmd: %v", err)

logger.Fatalf("error executing rootCmd: %v", err)

edwarnicke · 2021-11-23T14:43:22Z

I'm a bit confused how this connects to concurrent map panics in #419, could you explain?

denis-tingaikin · 2021-11-23T14:48:56Z

@edwarnicke

Sure. We are setting a setlogoptions at the top of the application.

So it conflicting with each connection here
https://github.com/networkservicemesh/sdk/blob/main/pkg/networkservice/common/setlogoption/server.go#L47

Imagine a few goroutines that are trying to work with this map.

Definitely, it is incorrect using of logging for top level of the application. We should not use the chain logging in the top of applications.

edwarnicke · 2021-11-23T14:52:21Z

Why does our logging involve a map with this risk? Does vanilla logrus have these issues?

denis-tingaikin · 2021-11-23T14:54:13Z

Why does our logging involve a map with this risk? Does vanilla logrus have these issues?

No, vanilla logrus doesn't have this issue. Currently, we are incorrect in using our logger from sdk for cmd-nsmgr.

edwarnicke · 2021-11-23T14:59:57Z

Got it. I look forward to seeing this land :)

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

Mixaster995 · 2021-11-24T10:41:50Z

@denis-tingaikin made requested changes - please, take a look

denis-tingaikin · 2021-11-24T12:09:52Z

main.go

 	}
 	logrus.SetLevel(level)

-	// Startup is finished
-	finish()


Hmm, this can be a major. Can we run here sFinish()?

We are passing combined logger further in manager. Isn't calling sFinish() will close span logger?

Yes, we can re-recreate the span logger for the next operation.

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

…d-nsmgr@main PR link: networkservicemesh/cmd-nsmgr#422 Commit: 9c48435 Author: Авраменко Михаил Date: 2021-11-25 15:12:52 +0700 Message: - Fix to prevent data races (#422) * removed unnecessary fields from context to prevent data races Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com> * fixed review comments Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com> * added traceCtx to manager Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com> * refactored after review comments Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com> * review refactoring Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com> * added spanlogger finish Signed-off-by: NSMBot <nsmbot@networkservicmesh.io>

denis-tingaikin reviewed Nov 22, 2021

View reviewed changes

Mixaster995 self-assigned this Nov 23, 2021

denis-tingaikin requested changes Nov 23, 2021

View reviewed changes

Mixaster995 mentioned this pull request Nov 23, 2021

Made group logger creation public networkservicemesh/sdk#1171

Merged

Mixaster995 added 5 commits November 24, 2021 17:35

removed unnecessary fields from context to prevent data races

ba50d5c

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

fixed review comments

0a060d7

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

added traceCtx to manager

179ccf8

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

refactored after review comments

d1a9461

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

review refactoring

223cdd5

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

Mixaster995 force-pushed the fix/logs-datarace branch from 4098b9f to 223cdd5 Compare November 24, 2021 10:41

denis-tingaikin reviewed Nov 24, 2021

View reviewed changes

added spanlogger finish

9260bad

Signed-off-by: Mikhail Avramenko <avramenkomihail15@gmail.com>

denis-tingaikin approved these changes Nov 25, 2021

View reviewed changes

denis-tingaikin merged commit 9c48435 into networkservicemesh:main Nov 25, 2021

nsmbot mentioned this pull request Nov 25, 2021

Update from update/networkservicemesh/cmd-nsmgr networkservicemesh/deployments-k8s#3851

Merged

Mixaster995 deleted the fix/logs-datarace branch November 25, 2021 09:22

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix to prevent data races #422

Fix to prevent data races #422

Mixaster995 commented Nov 22, 2021

denis-tingaikin Nov 22, 2021

Mixaster995 Nov 22, 2021

denis-tingaikin Nov 22, 2021

denis-tingaikin Nov 22, 2021 •

edited

Loading

Mixaster995 Nov 23, 2021

edwarnicke commented Nov 23, 2021

Mixaster995 commented Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

Mixaster995 Nov 23, 2021 •

edited

Loading

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021 •

edited

Loading

edwarnicke Nov 23, 2021

denis-tingaikin Nov 23, 2021

denis-tingaikin Nov 23, 2021

edwarnicke commented Nov 23, 2021

denis-tingaikin commented Nov 23, 2021 •

edited

Loading

edwarnicke commented Nov 23, 2021

denis-tingaikin commented Nov 23, 2021 •

edited

Loading

edwarnicke commented Nov 23, 2021

Mixaster995 commented Nov 24, 2021

denis-tingaikin Nov 24, 2021

Mixaster995 Nov 24, 2021

denis-tingaikin Nov 24, 2021

Mixaster995 Nov 25, 2021

		traceCtx := log.WithFields(ctx, map[string]interface{}{"cmd": os.Args[:1]})
		traceLogger, finish := utils.GetTraceLogger(traceCtx, "nsmgr")

-	traceCtx := log.WithFields(ctx, map[string]interface{}{"cmd": os.Args[:1]})
-	traceLogger, finish := utils.GetTraceLogger(traceCtx, "nsmgr")
+	_,  sLogger, _, sFinish := spanlogger.FromContext(ctx, "cmd-nsmgr")
+	defer sFinish()
+        _ , lLogger, lFinish := logruslogger.FromSpan(ctx, span, "cmd-nsmgr")
+        defer lFinish()
+        logger := log.New(sLogger, lLogger)

	jaegerCloser := jaeger.InitJaeger(traceCtx, "nsmgr")
	jaegerCloser := jaeger.InitJaeger(ctx, "nsmgr")

	traceLogger.Fatalf("error processing cfg from env: %+v", err)
	logger.Fatalf("error processing cfg from env: %+v", err)

		@@ -87,20 +87,21 @@ func (m *manager) initSecurity() (err error) {
		func RunNsmgr(ctx context.Context, configuration *config.Config) error {

	func RunNsmgr(ctx context.Context, configuration *config.Config) error {
	func RunNsmgr(ctx context.Context, logger log.Logger, configuration *config.Config) error {

	traceLogger.Fatalf("error executing rootCmd: %v", err)
	logger.Fatalf("error executing rootCmd: %v", err)

Fix to prevent data races #422

Fix to prevent data races #422

Conversation

Mixaster995 commented Nov 22, 2021

Description

Issue

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

denis-tingaikin Nov 22, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edwarnicke commented Nov 23, 2021

Mixaster995 commented Nov 23, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Mixaster995 Nov 23, 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

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

denis-tingaikin Nov 23, 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

edwarnicke commented Nov 23, 2021

denis-tingaikin commented Nov 23, 2021 • edited Loading

edwarnicke commented Nov 23, 2021

denis-tingaikin commented Nov 23, 2021 • edited Loading

edwarnicke commented Nov 23, 2021

Mixaster995 commented Nov 24, 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

denis-tingaikin Nov 22, 2021 •

edited

Loading

Mixaster995 Nov 23, 2021 •

edited

Loading

denis-tingaikin Nov 23, 2021 •

edited

Loading

denis-tingaikin commented Nov 23, 2021 •

edited

Loading

denis-tingaikin commented Nov 23, 2021 •

edited

Loading