[Regression]: Missing container logs when container exited

[strowk]

Testcontainers version

0.32.0

Using the latest Testcontainers version?

No

Host OS

Linux

Host arch

ARM

Go version

1.22.4

Docker version

Running on CI, cannot run this there

Docker info

Running on CI, cannot run this there

What happened?

Somewhere between versions v0.27.0 and v0.32.0 this library stopped printing out container logs whenever container failed and now I just have "failed to start container: container exited with code 1" in output. Please return previous behavior that helped troubleshooting.

Relevant log output

failed to start container: container exited with code 1

Additional information

No response

[mdelapenya]

Hi @strowk could you provide an code snippet or a reproduction repo for this? The error message you mentioned happens in the checkState function, that happens inside the wait strategies. So it seems something is causing the containers not to reach the desired state, but instead being in the "exited" one:

func checkState(state *types.ContainerState) error {
	switch {
	case state.Running:
		return nil
	case state.OOMKilled:
		return errors.New("container crashed with out-of-memory (OOMKilled)")
	case state.Status == "exited":
		return fmt.Errorf("container exited with code %d", state.ExitCode)
	default:
		return fmt.Errorf("unexpected container status %q", state.Status)
	}
}

Also it's interesting that the failed to start container log entry appears in our codebase for the testable examples in the modules, that's why I'm very interested in seeing your repro code to be able to debug it and find the root cause for this issue.

Could you provide that? 🙏

[mdelapenya]

@strowk I think I'm gonna close this issue as stale. Please reopen if you consider it's not done, adding a repro scenario 🙏

Thanks!

[strowk]

Not quite sure how to reproduce this. But probably the issue is caused by this change- #1971

This bit:

If it's too low the http connection to get the logs is too short and some logs might get missed randomly

sounds particularly suspicious to me :) looks like a bad design decision that would be causing problems for users who do not have time to read entire changelog and guess whether magic number 5.6 seconds is good or not in their particular case.. 😉

[strowk]

Hm, actually I an not so sure if explicitly 0.28 is an issue. I tried couple versions and I see different results:

in 0.28 there is plenty of useful info :

...

, while 0.32 just prints this:

, which does not help me at all at identifying the issue.

This turns out very easy to reproduce. Just go to "examples/nginx", break it like this:

WaitingFor:   wait.ForHTTP("/ttt").WithStartupTimeout(10 * time.Second),

instead of

WaitingFor:   wait.ForHTTP("/").WithStartupTimeout(10 * time.Second),

and then run go test in that folder.

Expected is an output like on the first pic - logs from container, logs from startup procedure, etc. So useful things helping to understand what went wrong.
Not expected output is like in 0.32:

go: downloading github.com/docker/docker v27.0.3+incompatible
go: downloading github.com/containerd/containerd v1.7.18
go: downloading github.com/containerd/errdefs v0.1.0
go: downloading github.com/Microsoft/hcsshim v0.11.5
go: downloading google.golang.org/grpc v1.59.0
go: downloading google.golang.org/genproto/googleapis/rpc v0.0.0-20231016165738-49dd2c1f3d0b
go: downloading github.com/klauspost/compress v1.17.4
--- FAIL: TestIntegrationNginxLatestReturn (10.90s)
    nginx_test.go:18: failed to start container: context deadline exceeded
FAIL
exit status 1
FAIL    github.com/testcontainers/testcontainers-go/examples/nginx      12.173s

this output gives zero information about what exactly went wrong. It seems that this library assumes that it is better to focus on the case when everything is ok, but this is the opposite of what the tests are for. The whole usefulness of tests is when they fail, not when they succeed (noone reads the output when all is fine..).

So please reopen @mdelapenya

[strowk]

I have bisected the problem up to version 0.32.0 . It was fine in 0.31.0 .

The specific reasoning for this inconvenient (at least for me) design decision comes from here - #1984

It would be ideal if the happy path (by default) logged as little as possible and reported only errors.

I think this suggestion might be misunderstood somewhat by implementation. Would it be possible that by "happy path" author meant "when there are no test failures", not "when users did not explicitly provide -v"?

There is sort of no way users would know when to run with "-v", since we do not know when test would fail? (if we knew that - we probably would not need to run them).

Made a PR that seems to make it work for me - #3459

I get that this is opinionated piece, but I have kind of a lot of experience with actually using this lib for lots of different cases and versions before 0.32 were significantly better in how quickly the issues in tests were kicked in actual real world applications.