Bug fix for data race

[yashrsharma44]

Changes made in this PR:

• Fix the data race bug - I have used locks wherever append is called.
• Updated the importing version of grpc-middleware in the provider module, so that the example tests use the latest example of the new logging API.

Fixes: #319
cc @johanbrandhorst
Signed-off-by: Yash Sharma yashrsharma44@gmail.com

[johanbrandhorst]

I think we need to rethink this mockLogger.

[johanbrandhorst]

Do we need a new mutex? Can't we use the same one we're embedding with baseMockLogger?

[johanbrandhorst]

Having read this a bit more closely, I think we should just merge baseMockLogger and mockLogger. I don't see what having two different structs here gives us, and it's really confusing to read. If we have a single mockLogger with a mutex that should make it easy to reason about where the locks need to be.

What do you think?

[yashrsharma44]

Hmm, I guess, we should merge both the baseMockLogger and mockLogger, which doesn't make sense to break down the logger into two parts.

Regarding the locks, I read that append operations and map operations are not concurrent safe, so I was using it as a rule of thumb for using the locks there. However, if you have more suggestions about the approach, I would be happy to discuss!

[johanbrandhorst]

I'm confused, I looked at the PR again and it doesn't look like you've made the change to merge these two loggers. Do you agree that this is a good idea? If so, could you please try to do it in this PR?

[yashrsharma44]

I kind of clicked on the review option by mistake 😛 I am currently working on merging the loggers, will ping you in slack once done.

[yashrsharma44]

I think we should keep the current structure, and change the name of baseMockLogger to sharedResults or sharedLogLines : More Info -
#354 (comment)

[codecov-io]

Codecov Report

Merging #354 into v2 will decrease coverage by 7.59%.
The diff coverage is 92.85%.

@@            Coverage Diff             @@
##               v2     #354      +/-   ##
==========================================
- Coverage   83.58%   75.98%   -7.60%     
==========================================
  Files          30       30              
  Lines         932      762     -170     
==========================================
- Hits          779      579     -200     
- Misses        114      137      +23     
- Partials       39       46       +7     

Impacted Files	Coverage Δ
chain.go	0.00% <ø> (-90.91%)	⬇️
interceptors/logging/payload.go	79.24% <50.00%> (-3.37%)	⬇️
interceptors/retry/retry.go	66.66% <70.00%> (-9.58%)	⬇️
interceptors/logging/interceptors.go	100.00% <100.00%> (ø)
interceptors/logging/logging.go	61.53% <100.00%> (-6.21%)	⬇️
interceptors/tags/fieldextractor.go	82.75% <100.00%> (-2.54%)	⬇️
interceptors/tracing/id_extract.go	76.92% <100.00%> (-8.27%)	⬇️
wrappers.go	50.00% <0.00%> (-50.00%)	⬇️
interceptors/tracing/metadata.go	50.00% <0.00%> (-16.67%)	⬇️
... and 27 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 73cf2ae...52d5001. Read the comment docs.

[yashrsharma44]

I had a few runs with the non-refactored code( the current setup) and the refactored code -

// THIS IS THE REFACTORED CODE WITH DATA RACE
type mockLogger struct {
	fields logging.Fields
	m      sync.Mutex
	lines  []LogLine
}

func (l *mockLogger) Lines() []LogLine {
	l.m.Lock()
	defer l.m.Unlock()

	return l.lines
}

func (l *mockLogger) Log(lvl logging.Level, msg string) {
	// since map isn't safe for concurrency, we use a lock
	l.m.Lock()
	defer l.m.Unlock()

	line := LogLine{
		lvl:    lvl,
		msg:    msg,
		fields: map[string]string{},
	}

	for i := 0; i < len(l.fields); i += 2 {
		line.fields[l.fields[i]] = l.fields[i+1]
	}

	l.lines = append(l.lines, line)
}

func (l *mockLogger) With(fields ...string) logging.Logger {
	// Append twice to copy slice, so we don't reuse array.
	l.m.Lock()
	defer l.m.Unlock()

	return &mockLogger{lines: l.lines, fields: append(append(logging.Fields{}, l.fields...), fields...)}
}

The code surprisingly doesn't have any data race for the current setup(using baseMockLogger and mockLogger) but when I merge it, there seems to be data race in spite of using locks .

I also want to merge the two loggers into one, but I am not able to find the issue of the failing tests due to the merged logger.
Suggestions are welcome.

[johanbrandhorst]

I've suggested some changes that should fix any existing race conditions in the new combined logger.

[yashrsharma44]

I applied the changes as you suggested, the data race issue has been removed, however, the fields are returning 0 data -

TestSuite/TestPing: interceptors_test.go:201: 
        	Error Trace:	interceptors_test.go:201
        	Error:      	"[]" should have 4 item(s), but has 0
        	Test:       	TestSuite/TestPing
=== RUN   TestSuite/TestPingError_WithCustomLevels
=== RUN   TestSuite/TestPingError_WithCustomLevels/Internal_must_remap_to_WarnLevel_in_DefaultClientCodeToLevel
    TestSuite/TestPingError_WithCustomLevels/Internal_must_remap_to_WarnLevel_in_DefaultClientCodeToLevel: interceptors_test.go:312: 
        	Error Trace:	interceptors_test.go:312
        	Error:      	"[]" should have 4 item(s), but has 0
        	Test:       	TestSuite/TestPingError_WithCustomLevels/Internal_must_remap_to_WarnLevel_in_DefaultClientCodeToLevel

[yashrsharma44]

I read the previous code closely, and wrote some notes about the working of the code -

• We have a baseMockerLogger which is a struct that contains a slice []LogLine that contains slice of results once we Log in the data.
• We have a mockLogger which contains a logger with a specific field.
• By using the With command, it creates another mockLogger, and copies the previous fields into the new logger along with the fields passed in the With function

So if we want to have a single logger, we need to think how to accumulate the final results in a variable that is shared among all the mockLoggers, so that when they perform the logging using Log the data is appended to that shared variable.

I think the current setup is good for the logic, maybe we can change the name of the baseMockLogger, to something sharedResults, that way it is clear why we are using a shared struct for storing results.

Do you have any idea to refactor this logic, because the current setup with name changes sounds good to me?
cc @johanbrandhorst

[johanbrandhorst]

Honestly I don't have enough understanding of this part of the code to know. I figured my suggested changes would fix the race, maybe we need to update how the tests read the final lines?

[yashrsharma44]

Yeah seems so, if we want a single logger, we need to think of how would we compare the results of logging.

[bwplotka]

This PR looks good to me, don't see the need of removing shared thing for test purposes as long as we comment it better and ensure result is sorted before check (:

[bwplotka]

I remember now. So this is essentially some kind of output (we can call it like this). Similar to os.StdErr. You push and it goes to some output. Normally it's shared so wanted to mimic this.

The problem might be that it's used concurrently so there is no way to guarantee order.

So we can either sort lines before comparing or remove sharedResult and keep references to all create loggers with With? Whatever works. Maybe if you name it output it will make more sense? (:

[yashrsharma44]

Great, thanks for confirming what I understood!

So we can either sort lines before comparing or remove sharedResult and keep references to all create loggers with With? Whatever works. Maybe if you name it output it will make more sense? (:

I think, I would keep the original method of comparing the results, that sounds much more dependable. The references might create a bug-prone experience for comparing the results, so I would stick with the original method.

I have renamed the sharedResults into mockStdOutput, and have added some comments for how we are using it as a shared struct. Would be happy to add more comments if needed.

I have also sorted the output lines so that we have a definitive order for comparing the values.

[yashrsharma44]

I have addressed @bwplotka comments, PTAL when you are free 😎

[yashrsharma44]

PR Reviewers : It would be nice if you could add the label hacktoberfest-accepted in this PR, so that this PR counts for hacktoberfest 😛

[johanbrandhorst]

Sorry for the radio silence on this, I haven't had the time to look at this for a while. I was hoping Bartek could get this over the line but he's been busy as well. We haven't forgotten about your work @yashrsharma44, and we appreciate it 🤗.

[yashrsharma44]

ping @bwplotka Please review this whenever you are free 🤗

[bwplotka]

LGTM!