GODRIVER-2986 Resolve failures in Race Detector Test

[prestonvasquez]

GODRIVER-2986

Summary

• Extend the change stream timeout in the "split large changes" change stream prose test added in GODRIVER-2827
• Guard read / write to the UST logger's lastOrder field, which is incremented every time the "info" method is called

Background & Motivation

[matthewdale]

It's not clear what log.mu guards access to and why we have to use atomic to increment log.lastOrder here but not compare or add log.lastOrder below. We should either use atomic to access shared values or synchronize the whole function, but not both.

[prestonvasquez]

Good point, I think it's safest to just keep the lock.

[matthewdale]

Optional: If you decide to synchronize access only to lastOrder, consider using an atomic.Int32 instead of a uint64. That would simplify the syntax, make checking for overflow easier, and make conversion to int safer (int32 -> int is always safe for the supported platforms).

E.g. simplified logic using an atomic.Int32:

order := log.lastOrder.Add(1)

// If lastOrder overflows, it will become negative. There are no
// other expected conditions where lastOrder should be negative.
if order < 0 {
	panic("lastOrder overflow")
}

if order > log.bufSize {
	return
}

log.logQueue <- orderedLogMessage{
	order:      int(order),
	logMessage: logMessage,
}

Even better, order is an intrinsic characteristic of a message on a channel. We don't actually need to atomically increment and record the order number here. Instead, we can increment an order number when we read the message off the channel here.

E.g.

go func() {
	defer close(orderedLogCh)
	defer close(unorderedLogCh)

	order := 0
	for actual := range logQueue(ctx, exp) {
		msg := actual.logMessage
		if _, ok := unorderedIndices[order]; ok {
			unorderedLogCh <- msg
		} else {
			orderedLogCh <- msg
		}
		order++
	}
}()

[prestonvasquez]

The order is principally used to determine when to close the logQueue channel, here.

[matthewdale]

Optional: If the number of messages sent will never exceed a 32-bit integer (and unexpected overflow is checked), it's safe to keep bufSize an int and do all the numeric conversions within the Info method.

[matthewdale]

Looks good 👍 .

I'd still like to understand why deferring incrementing causes a data race but incrementing at the end of the function doesn't, but we can defer that question.

[qingyang-hu]

I'd still like to understand why deferring incrementing causes a data race but incrementing at the end of the function doesn't, but we can defer that question.

Let's add a TODO there.

[prestonvasquez]

@qingyang-hu @matthewdale I think the defer theory is a red herring. The fact that we read and write to the order while "info" could (and is) used by multiple go routines will eventually result in a race condition regardless of where we increment the order. See this Go Playground example illustrating this behavior: https://go.dev/play/p/KfdcEe8G6qm

And this one where the problem is resolved by guarding the R/W of order: https://go.dev/play/p/sdAopPVwtMy

I think we should add a mutex to the "info" method to guard the order.

[matthewdale]

Looks good 👍