telemetryCounterMap.serialize reads counters and ranges the counter map without synchronisation

Summary

telemetryCounterMap guards its map with countersMutex, but only in Increment. serialize accesses the same state with no synchronisation at all, which gives two distinct problems — one a data race, one a fatal runtime error.

Because application telemetry is enabled by default in gocb, this is reachable with default settings against a cluster that supports app telemetry.

Affected: v10.9.1, v10.9.2, v10.9.3. apptelemetrymetrics.go is byte-identical in all three, so the newest release is affected too.

Detail

func (m *telemetryCounterMap) Increment(key telemetryCounterKey) {
	var counter *uint64

	m.countersMutex.Lock()
	counter, ok := m.counters[key]
	if !ok {
		counter = new(uint64)
		m.counters[key] = counter      // (2) map write, under the mutex
	}
	m.countersMutex.Unlock()

	atomic.AddUint64(counter, 1)       // (1) atomic counter write
}

func (m *telemetryCounterMap) serialize(counterName string) []string {
	var entries []string

	for k, v := range m.counters {     // (2) map read, NOT under the mutex
		...
		entries = append(entries, fmt.Sprintf("sdk_%s_r_%s{%s} %d",
			k.serviceAsString(), counterName, tags, *v))   // (1) non-atomic counter read
	}

	return entries
}

1. apptelemetrymetrics.go:352 — *v is a plain load of a counter that Increment writes with atomic.AddUint64. This is a data race, and it is what the race detector reports.

2. apptelemetrymetrics.go:344 — ranging m.counters concurrently with Increment's insertion is a concurrent map read and map write. The runtime detects this independently of -race and calls fatal("concurrent map read and map write"), which is not recoverable. This is the more serious of the two, since it can terminate the process rather than merely being reported under test.

In v10.9.3, countersMutex appears at lines 324, 330 and 336 — that is, in the type declaration and in Increment only. serialize never takes it.

The two functions run concurrently by construction: serialize is reached from the telemetry websocket goroutine (TelemetryReporter.exportMetrics → telemetryWebsocketClient.readWritePump), while Increment is reached from connection goroutines (memdClient.resolveRequest → recordTelemetry). New counter keys are created per agent/service/node/bucket, so the insertion window opens on topology changes, failover, and the first operations against a node — which is why this presents as intermittent rather than constant.

Race detector output

Observed on v10.9.1 (line numbers below are that version's; the file is unchanged through v10.9.3):

WARNING: DATA RACE
Read at 0x00c001cdb618 by goroutine 209:
  gocbcore/v10.(*telemetryCounterMap).serialize()          apptelemetrymetrics.go:352
  gocbcore/v10.(*telemetryCounters).serialize()            apptelemetrymetrics.go:160
  gocbcore/v10.(*telemetryMetrics).serialize()             apptelemetrymetrics.go:383
  gocbcore/v10.(*TelemetryReporter).exportMetrics()        apptelemetry.go:81
  gocbcore/v10.CreateTelemetryReporter.func1()             apptelemetry.go:90
  gocbcore/v10.(*telemetryWebsocketClient).readWritePump() apptelemetrywebsocketclient.go:354

Previous write at 0x00c001cdb618 by goroutine 250:
  sync/atomic.AddUint64()
  gocbcore/v10.(*telemetryCounters).recordOp()             apptelemetrymetrics.go:154
  gocbcore/v10.(*telemetryMetrics).recordOperationCompletion()  apptelemetrymetrics.go:394
  gocbcore/v10.(*TelemetryReporter).recordOperationCompletion() apptelemetry.go:70
  gocbcore/v10.(*telemetryComponent).RecordOp()            apptelemetry.go:229
  gocbcore/v10.(*memdClient).recordTelemetry()             memdclient.go:806
  gocbcore/v10.(*memdClient).resolveRequest()              memdclient.go:430

Same address in both stacks.

Reproduction

Run a -race integration suite against a real cluster using gocb with default options and enough KV traffic to create counter keys. We observed roughly 1 failure in 5 full suite runs of about 3 minutes each.

Setting AppTelemetryConfig{Disabled: true} eliminates it entirely, which is consistent with the diagnosis: gocb then leaves appTelemetryReporter nil, so the reporter and its websocket goroutine are never created and serialize is never called. With telemetry left at its default we saw the failure recur; with it disabled, 12 consecutive full runs were clean.

Worth noting for anyone else hitting this: the failure carries no assertion message of its own — just race detected during execution of test — and is attributed to a different test on each run, while passing when that test is run in isolation. It reads like a test-interaction problem, which is what made it slow to identify.

Suggested fix

Hold countersMutex for the map iteration, and load each counter atomically:

func (m *telemetryCounterMap) serialize(counterName string) []string {
	var entries []string

	m.countersMutex.Lock()
	defer m.countersMutex.Unlock()

	for k, v := range m.counters {
		...
		entries = append(entries, fmt.Sprintf("sdk_%s_r_%s{%s} %d",
			k.serviceAsString(), counterName, tags, atomic.LoadUint64(v)))
	}

	return entries
}

If holding the lock across the whole serialization is undesirable, snapshotting the key/pointer pairs under the lock and formatting outside it addresses (2), and atomic.LoadUint64 is still needed for (1).

telemetryHistogramMap may warrant a look for the same shape.

Happy to move this to JIRA if that is the preferred channel — the README does not say.

Start in apptelemetrymetrics.go at telemetryCounterMap.serialize and compare its access to countersMutex usage in Increment. Run the race-enabled integration suite with application telemetry enabled and enough KV traffic to exercise counter creation; done means concurrent serialization no longer reports a race or fatal map access, while telemetry-disabled runs remain unaffected.