[Bug]: Attaching a LogConsumer to a container makes the test hang if the container exits

[nadiamoe]

Testcontainers version

v0.24.1

Using the latest Testcontainers version?

Yes

Host OS

Linux

Host arch

x86

Go version

1.21

Docker version

Client:
 Version:           24.0.5
 API version:       1.43
 Go version:        go1.20.6
 Git commit:        ced0996600
 Built:             Wed Jul 26 21:44:58 2023
 OS/Arch:           linux/amd64
 Context:           default

Server:
 Engine:
  Version:          24.0.5
  API version:      1.43 (minimum version 1.12)
  Go version:       go1.20.6
  Git commit:       a61e2b4c9c
  Built:            Wed Jul 26 21:44:58 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.7.6
  GitCommit:        091922f03c2762540fd057fba91260237ff86acb.m
 runc:
  Version:          1.1.9
  GitCommit:        
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Docker info

Client:
 Version:    24.0.5
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  0.11.2
    Path:     /usr/lib/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  2.20.3
    Path:     /usr/lib/docker/cli-plugins/docker-compose

Server:
 Containers: 5
  Running: 1
  Paused: 0
  Stopped: 4
 Images: 51
 Server Version: 24.0.5
 Storage Driver: zfs
  Zpool: zsstripe
  Zpool Health: ONLINE
  Parent Dataset: zsstripe/docker
  Space Used By Parent: 30240198656
  Space Available: 196123287552
  Parent Quota: no
  Compression: zstd-fast
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 091922f03c2762540fd057fba91260237ff86acb.m
 runc version: 
 init version: de40ad0
 Security Options:
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.1.53-1-lts
 Operating System: Arch Linux
 OSType: linux
 Architecture: x86_64
 CPUs: 6
 Total Memory: 31.28GiB
 Name: Archiroo
 ID: 27XO:IXYL:U5CA:XTZQ:Y4BL:LF3Q:JRWK:WLYJ:2RNN:CCAE:NEBA:DJHF
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Username: roobre
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

What happened?

When running a GenericContainer c that terminates unexpectedly, if a LogConsumer has been attached to the container with c.FollowOutput and started with c.StartLogProducer, calls to c.StopLogProducer will block forever. As c.Terminate calls c.StopLogProducer, this will cause a test to hang indefinitely if c.Terminate is called in t.Cleanup.

See the following example:

package testcon_test

import (
	"context"
	"testing"
	"time"

	"github.com/testcontainers/testcontainers-go"
	"github.com/testcontainers/testcontainers-go/wait"
)

// Mirror is a testcontainers log adapter that mirrors container output to testing.T.Log.
type Mirror struct {
	T *testing.T
}

// Accept implements the testcontainers adapter interface by writing received output to the test logger.
func (m Mirror) Accept(log testcontainers.Log) {
	m.T.Logf("%s: %s", log.LogType, log.Content)
}

func TestTerminates(t *testing.T) {
	debian, err := testcontainers.GenericContainer(context.TODO(), testcontainers.GenericContainerRequest{
		ProviderType: testcontainers.ProviderDocker,
		ContainerRequest: testcontainers.ContainerRequest{
			Image:      "debian",
			Cmd:        []string{"/bin/sh", "-c", "echo ready && sleep 1 && exit 1"},
			WaitingFor: wait.ForLog("ready"),
		},
		Started: true,
	})
	if err != nil {
		t.Fatal(err)
	}

	t.Cleanup(func() {
		debian.Terminate(context.TODO())
	})

	debian.FollowOutput(Mirror{T: t})
	err = debian.StartLogProducer(context.TODO())
	if err != nil {
		t.Fatal(err)
	}

	time.Sleep(5 * time.Second)
}

The test above produces the output below and never terminates unless I send and interrupt with C-c.

This happens regardless of the exit code of the container.

Relevant log output

11:22:57 ~/Staging/testcon-repro $> go test -v ./
=== RUN   TestTerminates
2023/09/22 11:22:58 github.com/testcontainers/testcontainers-go - Connected to docker:
  Server Version: 24.0.5
  API Version: 1.43
  Operating System: Arch Linux
  Total Memory: 32030 MB
  Resolved Docker Host: unix:///var/run/docker.sock
  Resolved Docker Socket Path: /var/run/docker.sock
  Test SessionID: 646e587aee8704cdd7fc09403c34e30f3267265314af5a43d98d4fd089daf4ca
  Test ProcessID: 30ba444c-ee29-48ca-bdfb-26101b5291c7
2023/09/22 11:22:58 🐳 Creating container for image docker.io/testcontainers/ryuk:0.5.1
2023/09/22 11:22:59 ✅ Container created: f2393a6e5e8a
2023/09/22 11:22:59 🐳 Starting container: f2393a6e5e8a
2023/09/22 11:22:59 ✅ Container started: f2393a6e5e8a
2023/09/22 11:22:59 🚧 Waiting for container id f2393a6e5e8a image: docker.io/testcontainers/ryuk:0.5.1. Waiting for: &{Port:8080/tcp timeout:<nil> PollInterval:100ms}
2023/09/22 11:22:59 🐳 Creating container for image debian
2023/09/22 11:22:59 ✅ Container created: 7909c158052a
2023/09/22 11:22:59 🐳 Starting container: 7909c158052a
2023/09/22 11:23:00 ✅ Container started: 7909c158052a
2023/09/22 11:23:00 🚧 Waiting for container id 7909c158052a image: debian. Waiting for: &{timeout:<nil> Log:ready IsRegexp:false Occurrence:1 PollInterval:100ms}
    testcon_test.go:19: STDOUT: ready
container log error: EOF. Stopping log consumer: Headers out of sync2023/09/22 11:23:05 🐳 Terminating container: 7909c158052a
^Csignal: interrupt
FAIL	testconrepro	24.862s

Additional information

No response

[nadiamoe]

After giving this a bit of a deeper look, I suspect the problem might be in this part of the code:

testcontainers-go/docker.go

Lines 665 to 667 in 51cde33

	_, _ = fmt.Fprintf(os.Stderr, "container log error: %+v. %s", err, logStoppedForOutOfSyncMessage)
	// if we would continue here, the next header-read will result into random data...
	return

Where, if an error occurs while reading the logs (such as the container getting terminated), the goroutine returns and never consumes stop:

testcontainers-go/docker.go

Line 644 in 51cde33

case <-stop:

Terminate will by default attempt to send a bool to that channel, which blocks forever as no one is receiving on the other end.

There seems to be an ongoing PR (#1278) revamping this code.

[mdelapenya]

Thanks for digging into it @roobre, indeed, I'm focusing this week in bugs, and I'll tackle that PR ASAP. IIRC there is a missing thing regarding running the code multiple times with

for x in {1..20}; do go test -timeout 600s -run ^Test_StartStop$ github.com/testcontainers/testcontainers-go -count=1; done

But I need to go back to it this week

[jrfeenst]

Could be the same issue as #1407

[mdelapenya]

@roobre I'm closing this one as a duplicate of #1407.

Thanks for your support, and sorry for taking that long in responding. Many times, the backlog gets shadowed by day-to-day duties 😞