Go 1.23 timer changes can lead to hangs

[dany74q]

Description

Go 1.23 timer semantic changes the timer channels to be non-buffered;
One side effect of this is that now, trying to drain timer channels after calling t.Stop() will always block.

We've observed occasional hangs coming from the timer channel drain in batch_span_processor.go:

func (bsp *batchSpanProcessor) processQueue() {
[...]
if shouldExport {
	if !bsp.timer.Stop() {
		<-bsp.timer.C // <<- This hangs in go 1.23 w/ the default asynctimerchan=0 
	}

goroutine 1 [select, 23 minutes]:
go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).Shutdown.func1()
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:170 +0x108
sync.(*Once).doSlow(0x40001e4120?, 0x4013d17000?)
        /usr/local/go/src/sync/once.go:76 +0xf8
sync.(*Once).Do(...)
        /usr/local/go/src/sync/once.go:67
go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).Shutdown(0x40001b8058?, {0x1cec97c8?, 0x2e7794c0?})
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:156 +0x60

goroutine 1096971 [semacquire, 23 minutes]:
sync.runtime_Semacquire(0x7365756c6176222c?)
        /usr/local/go/src/runtime/sema.go:71 +0x2c
sync.(*WaitGroup).Wait(0x4005ddd790)
        /usr/local/go/src/sync/waitgroup.go:118 +0x74
go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).Shutdown.func1.1()
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:161 +0x50
created by go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).Shutdown.func1 in goroutine 1
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:159 +0xc8

goroutine 151 [chan receive, 38 minutes]:
go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).processQueue(0x4005ddd720)
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:330 +0x2dc
go.opentelemetry.io/otel/sdk/trace.NewBatchSpanProcessor.func1()
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:128 +0x54
created by go.opentelemetry.io/otel/sdk/trace.NewBatchSpanProcessor in goroutine 1
        /tmp/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.24.0/trace/batch_span_processor.go:126 +0x2b8

Environment

• OS: linux
• Architecture: arm64
• Go Version: 1.23
• opentelemetry-go version: v1.24.0

[dany74q]

We can fix this by select-ing on the channel:
#5869

[dmathieu]

Fixed in #5869.

[ash2k]

I don't think there was a change in semantics - that would have broken the Go 1 compatibility promise. This program works as expected: https://go.dev/play/p/KGLGXCurLA_o.

What you saw was probably this bug. Go 1.23.0 and 1.23.1 are affected, 1.23.2 has the fix.

[pellared]

@ash2k

I don't think there was a change in semantics - that would have broken the Go 1 compatibility promise.

See:

• https://tip.golang.org/doc/go1.23#timer-changes
• https://go.dev/wiki/Go123Timer
• find "Go 1.23" in https://pkg.go.dev/time

This program works as expected: https://go.dev/play/p/KGLGXCurLA_o.

In your snippet t.Stop() should never return false (thanks to the bugfix you mentioned). However, in case using the timer in multiple goroutines a deadlock can still happen e.g. https://go.dev/play/p/vEFtZgmzU-s. The other possibility is that the same goroutine calls t.Stop twice e.g. https://go.dev/play/p/dgIVo7SM3iv.

[ash2k]

I think both examples you provided are buggy use of timers. I'd expect them to deadlock in any version. 🤷

[pellared]

I think both examples you provided are buggy use of timers. I'd expect them to deadlock in any version. 🤷

@ash2k, you are right. They deadlock in Go 1.22 as well. I only see a difference between Go 1.22 and Go 1.23 in the output for the following example https://go.dev/play/p/iVkFnd5gVc8.

After experimenting and reading a few times it looks like we could indeed revert the bugfix thanks to the fix for golang/go#69312.

On the other side, the current code is still correct and more defensive (e.g. works for people who have not patched Go 1.23). Therefore, maybe it is better to leave it as it is.

Do you have any preference/suggestion on what we should do and why?

Personally, I have no strong preference.

PS. Thanks a lot for taking your time to needed to give us feedback. I truly appreciate your effort.

[ash2k]

Do you have any preference/suggestion on what we should do and why?

I don't think there is a lot of sense to keep the workaround - there is so much code using timers that is broken by the Go bug, that having a workaround in a single place doesn't make sense. Also, looks like the current timer code is buggy if used with Go 1.22 and needs to be reworked anyway:

ForceFlush() can be called at any time. It calls exportSpans() in a new goroutine:

opentelemetry-go/sdk/trace/batch_span_processor.go

Lines 178 to 206 in b3c313f

	func (bsp *batchSpanProcessor) ForceFlush(ctx context.Context) error {
	// Interrupt if context is already canceled.
	if err := ctx.Err(); err != nil {
	return err
	}
	// Do nothing after Shutdown.
	if bsp.stopped.Load() {
	return nil
	}
	var err error
	if bsp.e != nil {
	flushCh := make(chan struct{})
	if bsp.enqueueBlockOnQueueFull(ctx, forceFlushSpan{flushed: flushCh}) {
	select {
	case <-bsp.stopCh:
	// The batchSpanProcessor is Shutdown.
	return nil
	case <-flushCh:
	// Processed any items in queue prior to ForceFlush being called
	case <-ctx.Done():
	return ctx.Err()
	}
	}
	wait := make(chan error)
	go func() {
	wait <- bsp.exportSpans(ctx)

exportSpans() resets the timer:

opentelemetry-go/sdk/trace/batch_span_processor.go

Lines 262 to 264 in b3c313f

	// exportSpans is a subroutine of processing and draining the queue.
	func (bsp *batchSpanProcessor) exportSpans(ctx context.Context) error {
	bsp.timer.Reset(bsp.o.BatchTimeout)

For Go 1.22 time#Timer.Reset says:

For a Timer created with NewTimer, Reset should be invoked only on stopped or expired timers with drained channels.

This is not the case for the code above. exportSpans() cannot assume that the timer has expired.

---

With Go 1.23 looks like this is safe to do.

So, if we want to be compatible with Go 1.22 then the code needs to be reworked to be more careful with the timer. There may be other code too, I haven't looked.

[ash2k]

I think there is a goroutine leak in ForceFlush():

opentelemetry-go/sdk/trace/batch_span_processor.go

Lines 204 to 214 in b3c313f

	wait := make(chan error)
	go func() {
	wait <- bsp.exportSpans(ctx)
	close(wait)
	}()
	// Wait until the export is finished or the context is cancelled/timed out
	select {
	case err = <-wait:
	case <-ctx.Done():
	err = ctx.Err()
	}

If context is canceled before exportSpans() returns, nothing would receive from the channel and the goroutine will be stuck. Chanel needs to be buffered to have space for the error value.

Also, no need to close the channel.