reader go routine hangs and leaks when Connection.Close() is called multiple times

[fho]

Hello,

we are using go.uber.org/goleak for our internal amqp wrapper package and stumbled over a go-routine leak.
This happens in an internal testcase where we send 2 messages to a non-existing exchange. This causes an error that is received by our reconnect goroutine on the NotifyClose channel which to close the connection and then the connection is also closed in our client (after the reconnect go-routine terminated).
In our testcase we only call 1x close on the channel (unnecessary) and 1x Close on the connection.

I managed to reproduce the same hang and go-routine leak when calling Close in parallel on the same connection. This is not the same scenario that happens in our internal testcase but it reproduces it. :-)

I'm using amqp091-go commit 6cac2fa.

This issue can be reproduced with the following testcase:

//go:build integration
// +build integration

package amqp091

import (
	"sync"
	"testing"

	"go.uber.org/goleak"
)

func TestGoRoutineLeakOnParallelConClose(t *testing.T) {
	const routines = 2
	defer goleak.VerifyNone(t)
	c := integrationConnection(t, t.Name())

	var wg sync.WaitGroup
	startSigCh := make(chan interface{})

	for i := 0; i < routines; i++ {
		wg.Add(1)
		go func(id int) {
			defer wg.Done()

			<-startSigCh

			err := c.Close()
			if err != nil {
				t.Logf("close failed in routine %d: %s", id, err.Error())
			}
		}(i)
	}
	close(startSigCh)

	t.Log("waiting for go-routines to terminate")
	wg.Wait()
}

Test output:

=== RUN   TestGoRoutineLeakOnParallelConClose
    bug_test.go:36: waiting for go-routines to terminate
    bug_test.go:30: close failed in routine 0: Exception (504) Reason: "channel/connection is not open"
    leaks.go:78: found unexpected goroutines:
        [Goroutine 11 in state chan send, with github.com/rabbitmq/amqp091-go.(*Connection).dispatch0 on top of the stack:
        goroutine 11 [chan send]:
        github.com/rabbitmq/amqp091-go.(*Connection).dispatch0(0xc0001263c0, {0x8c5828?, 0xc00000e240})
        	/home/fho/git/amqp091-go/connection.go:483 +0x40f
        github.com/rabbitmq/amqp091-go.(*Connection).demux(0xc00005af18?, {0x8c5828, 0xc00000e240})
        	/home/fho/git/amqp091-go/connection.go:456 +0x59
        github.com/rabbitmq/amqp091-go.(*Connection).reader(0xc0001263c0, {0x8c4980?, 0xc000010068})
        	/home/fho/git/amqp091-go/connection.go:550 +0x225
        created by github.com/rabbitmq/amqp091-go.Open
        	/home/fho/git/amqp091-go/connection.go:251 +0x5eb
        ]
--- FAIL: TestGoRoutineLeakOnParallelConClose (0.46s)

On my machine it happens on almost every execution, some succeed without the leak though.
It might be necessary to run the testcase multiple times to run into the issue:

while go test -race -count=1 -run=TestGoRoutineLeakOnParallelConClose -v -tags integration; do : ; done

Update:
I think I now understand how it happens:

• Close() is called 2x, both calls send out a close message¹
• For both messages the reader reads the response frame, calls c.demux() and passed the msg to the rpc chan²
• The shutdown closes the errors channel³
• for one of the received responses the call() method did not read the msg from the rpc channel yet, it is waiting in the select loop⁴, because the errors channel is closed the call() returns without reading the msg from the rpc channel, the reader go-routine hangs forever in dispatch0() trying to send the msg to the rpc channel ² because it is unbuffered

I guess this scenario, that call() returns before reading a msg from the rpc chan could also get triggered when Close() is called only 1x but an error happened, shortly after a message response was received.
call() could return because an error is read from c.errors while dispatch0 is sending a message to the rpc chan.

Footnotes

1. https://github.com/rabbitmq/amqp091-go/blob/6cac2faf74b0e761395b4da4ebfa3fe4a8eb8b59/connection.go#L350 ↩

2. https://github.com/rabbitmq/amqp091-go/blob/6cac2faf74b0e761395b4da4ebfa3fe4a8eb8b59/connection.go#L483 ↩ ↩²

3. https://github.com/rabbitmq/amqp091-go/blob/6cac2faf74b0e761395b4da4ebfa3fe4a8eb8b59/connection.go#L425 ↩

4. https://github.com/rabbitmq/amqp091-go/blob/6cac2faf74b0e761395b4da4ebfa3fe4a8eb8b59/connection.go#L692 ↩