Fix data races in the logger module #1414

typeless · 2017-03-30T10:35:45Z

strk

I see some locking being added which could be good, but would prefer seeing defer in use rather than manual unlock which might be easier to overlook on early returns.

strk · 2017-03-30T10:39:49Z

Makefile

@@ -93,7 +93,7 @@ install: $(wildcard *.go)
 build: $(EXECUTABLE)

 $(EXECUTABLE): $(SOURCES)
-	go build -i -v -tags '$(TAGS)' -ldflags '-s -w $(LDFLAGS)' -o $@
+	go build -race -i -v -tags '$(TAGS)' -ldflags '-s -w $(LDFLAGS)' -o $@


I don't think this belongs here, but feel free to send another PR adding a "debug-build" makefile rule.

Yes. I am trying to figure out how to remove it from the commit.

strk · 2017-03-30T10:40:36Z

modules/log/log.go

@@ -212,13 +212,13 @@ func (l *Logger) SetLogger(adapter string, config string) error {
 // DelLogger removes a logger adapter instance.
 func (l *Logger) DelLogger(adapter string) error {
 	l.lock.Lock()
-	defer l.lock.Unlock()


Is the defer responsible of a race condition ?

strk · 2017-03-30T10:48:44Z

You could just add a new commit and postpone cleanups to later (when we're all happy you can use something like `git rebase -i origin/master` and squash all commits togheter)

strk · 2017-03-30T10:55:14Z

modules/log/log.go

 			for _, l := range l.outputs {
 				if err := l.WriteMsg(bm.msg, bm.skip, bm.level); err != nil {
 					fmt.Println("ERROR, unable to WriteMsg:", err)
 				}
 			}
+			l.lock.Unlock()


Replace this with a defer on the line after the .Lock() call

This one is a bit of tricky and I am afraid it would cause dead-lock if the select statement is included.

Is the case block not a scope considered by defer ? Does -race also check for deadlocks ?

I expected defer is function scoped. Correct me if I am wrong.
I am not sure about deadlocks detection of -race. I suppose it doesn't help.

strk · 2017-03-30T10:55:20Z

modules/log/log.go

 	for _, l := range l.outputs {
 		l.Flush()
 	}
+	l.lock.Unlock()


Replace this with a defer on the line after the .Lock() call

strk · 2017-03-30T10:55:25Z

modules/log/log.go

@@ -297,6 +302,7 @@ func (l *Logger) Close() {
 			break
 		}
 	}
+	l.lock.Unlock()


Replace this with a defer on the line after the .Lock() call

I guess I have bug here as the lock encloses some synchronization points (is this the correct terminology?).

strk · 2017-03-30T11:16:57Z

On Thu, Mar 30, 2017 at 04:07:49AM -0700, Mura Li wrote: I expected defer is function scoped. Correct me if I am wrong.

It seems you're right about this

And locking the shared data structure accurately.

typeless · 2017-03-30T14:15:05Z

I took a closer look into the code and replaced the mutex with an r/w mutex. Also I think protecting the specific data tighter is better.

A wrapper struct for the map might or might not worth the effort and complexity. But if syncmap becomes a thing. we could migrate our shared maps to using it.

Edit: https://godoc.org/golang.org/x/sync/syncmap ~~I haven't figured out how to use it (especially the for ... range part)~~. Hmm, using syncmap might be a good idea.

strk · 2017-03-30T15:04:45Z

LGTM and you can try the syncmap in a separate PR maybe

ptman · 2017-03-30T16:56:22Z

modules/log/log.go

-		if _, ok := l.outputs[mode]; ok {
+		l.lock.RLock()
+		_, ok := l.outputs[mode]
+		l.lock.RUnlock()


Doesn't this cause a race between checking and removing?

You are correct. Fixed.

ptman · 2017-03-30T16:57:15Z

modules/log/log.go

@@ -174,7 +177,7 @@ type logMsg struct {
 // it can contain several providers and log message into all providers.
 type Logger struct {
 	adapter string
-	lock    sync.Mutex
+	lock    sync.RWMutex


Is this the lock for the logger struct or for outputs?

I think It's for the outputs.

Normally, locks should be per data instead of a chunk of code. And I don't see any other fields except for 'outputs', would be updated concurrently. And channel variables should be thread-safe in its own right.

My point was, that reading the code, a lock called lock, with no comments, doesn't make it clear to me that it's a lock for outputs. I would add a comment, or name it outputsLock or something similar. But #1421 is also an option.

Fair enough. Typically the idiomatic way would be to wrap the map in a new type with its own lock. Now that we have syncmap, we can just use it.

typeless · 2017-03-31T05:46:37Z

In favor of #1421

Fix data races

bce07fd

typeless force-pushed the fix-races-of-logger branch from 3cf7530 to bce07fd Compare March 30, 2017 10:40

strk suggested changes Mar 30, 2017

View reviewed changes

Follow the defer pattern

38e7ce3

tboerger added the lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. label Mar 30, 2017

Remove -race. This shouldn't be in production code.

1915793

strk suggested changes Mar 30, 2017

View reviewed changes

Follow the defer-unlock pattern

7974b2a

lunny added this to the 1.2.0 milestone Mar 30, 2017

lunny added the type/bug label Mar 30, 2017

typeless added 2 commits March 30, 2017 19:56

Avoid deadlocks

67278d2

Use RWMutex instead of Mutex

31394cf

And locking the shared data structure accurately.

ptman reviewed Mar 30, 2017

View reviewed changes

Fix read-and-update race

f20a686

tboerger added lgtm/need 1 This PR needs approval from one additional maintainer to be merged. and removed lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. labels Mar 31, 2017

typeless closed this Mar 31, 2017

lunny removed this from the 1.2.0 milestone Mar 31, 2017

typeless deleted the fix-races-of-logger branch April 3, 2019 04:59

go-gitea locked and limited conversation to collaborators Nov 24, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix data races in the logger module #1414

Fix data races in the logger module #1414

typeless commented Mar 30, 2017

strk left a comment

strk Mar 30, 2017

typeless Mar 30, 2017

strk Mar 30, 2017

typeless Mar 30, 2017

strk commented Mar 30, 2017 via email

strk Mar 30, 2017

typeless Mar 30, 2017

strk Mar 30, 2017

typeless Mar 30, 2017

strk Mar 30, 2017

typeless Mar 30, 2017

strk Mar 30, 2017

typeless Mar 30, 2017 •

edited

Loading

strk commented Mar 30, 2017 via email

typeless commented Mar 30, 2017 •

edited

Loading

strk commented Mar 30, 2017

ptman Mar 30, 2017

typeless Mar 31, 2017

ptman Mar 30, 2017

typeless Mar 31, 2017

ptman Mar 31, 2017

typeless Mar 31, 2017

typeless commented Mar 31, 2017

Fix data races in the logger module #1414

Fix data races in the logger module #1414

Conversation

typeless commented Mar 30, 2017

strk 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

strk commented Mar 30, 2017 via email

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

typeless Mar 30, 2017 • edited Loading

Choose a reason for hiding this comment

strk commented Mar 30, 2017 via email

typeless commented Mar 30, 2017 • edited Loading

strk commented Mar 30, 2017

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

typeless commented Mar 31, 2017

typeless Mar 30, 2017 •

edited

Loading

typeless commented Mar 30, 2017 •

edited

Loading