Retry failed calls to MappedPort to workaround inspect problem

[tylfin]

What does this PR do?

Add a retry loop to the MappedPort call in the docker package.

Why is it important?

After some investigation into #605, it looks like Docker will sometimes return information from inspectContainer that doesn't include the NetworkSettings. This makes requests to GenericContainer fail intermittently.

Related issues

• Closes [Bug]: Endpoint() returns "port not found" error, even though wait.ForListeningPort is used #605

[netlify]

✅ Deploy Preview for testcontainers-go ready!

Name	Link
🔨 Latest commit	6c70284
🔍 Latest deploy log	https://app.netlify.com/sites/testcontainers-go/deploys/662125476091020008bb6f1c
😎 Deploy Preview	https://deploy-preview-2479--testcontainers-go.netlify.app
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

---

To edit notification comments on pull requests, go to your Netlify site configuration.

[mdelapenya]

As a follow-up, I'm going to evaluate the impact of this change in the case there are multiple calls to the inspect method, as I'm suspicious it's not caching the response properly.

Other than that, LGTM, thanks!

[tylfin]

Thanks @mdelapenya, this worked locally for me and I can reproduce it fairly consistently if you want me to change anything. The backoff isn't necessary if you'd like me to make the retries instant instead.

[mdelapenya]

It looks like Docker will sometimes return information from inspectContainer that doesn't include the NetworkSettings

As you can reproduce it fairly consistently, could you expand on this? I can now talk to the Docker folks regarding this and share this feedback 🙏

[tylfin]

Sure thing, my setup is fairly straightforward:

...
req := testcontainers.ContainerRequest{
	Mounts: []testcontainers.ContainerMount{},
	Env:    map[string]string{},
	Files:  []testcontainers.ContainerFile{},
	Cmd:    []string{"/usr/local/bin/startup.sh"},
}

genericReq := testcontainers.GenericContainerRequest{
	ContainerRequest: req,
	Started:          true,
	Reuse:            false,
}

for _, opt := range opts {
	opt.Customize(&genericReq)
}

container, err := testcontainers.GenericContainer(ctx, genericReq)
if err != nil {
	return nil, err
}
...

With the opts exposing the port (:4242) and adding the appropriate wait strategies:

...
wait.ForHTTP("/__api__/status").WithPort(containerPortWithProtocol).WithStartupTimeout(util.StartupTimeout),
...
	return func(req *testcontainers.GenericContainerRequest) {
		req.ExposedPorts = append(req.ExposedPorts, "4242/tcp")
...

Now when I modify Ports():

func (c *DockerContainer) Ports(ctx context.Context) (nat.PortMap, error) {
	inspect, err := c.inspectContainer(ctx)
	if err != nil {
		return nil, err
	}

	fmt.Printf("%+v\n%+v\n+%+v", inspect, inspect.NetworkSettings, inspect.Config)

	return inspect.NetworkSettings.Ports, nil
}

I occasionally get the error message: failed to start container: port not found with logs:

&{NetworkSettingsBase:{Bridge: SandboxID:fee401998fde9a843fba7eab7062b1ec79ec92cca61637f2aa9b6d125626a6de SandboxKey:/var/run/docker/netns/fee401998fde Ports:map[5432/tcp:[{HostIP:0.0.0.0 HostPort:52850}]] HairpinMode:false LinkLocalIPv6Address: LinkLocalIPv6PrefixLen:0 SecondaryIPAddresses:[] SecondaryIPv6Addresses:[]} DefaultNetworkSettings:{EndpointID:b57c9637697566aaf2bb9db3f812d346d8b08d1d05672bdfbb9b58d170a07990 Gateway:172.17.0.1 GlobalIPv6Address: GlobalIPv6PrefixLen:0 IPAddress:172.17.0.4 IPPrefixLen:16 IPv6Gateway: MacAddress: redacted} Networks:map[bridge:0x1400065e7e0]}
&{NetworkSettingsBase:{Bridge: SandboxID:9c3cfc54b8e53e06be36d20ad521caab153034a4f708abab0672496c1c36f4ef SandboxKey:/var/run/docker/netns/9c3cfc54b8e5 Ports:map[4242/tcp:[]] HairpinMode:false LinkLocalIPv6Address: LinkLocalIPv6PrefixLen:0 SecondaryIPAddresses:[] SecondaryIPv6Addresses:[]} DefaultNetworkSettings:{EndpointID:2d5a0b8307b28f27c51ef0d162a24bbdb1ec61f9078daa253335cd51726633e9 Gateway:172.17.0.1 GlobalIPv6Address: GlobalIPv6PrefixLen:0 IPAddress:172.17.0.5 IPPrefixLen:16 IPv6Gateway: redacted} Networks:map[bridge:0x140006cc0e0]}
&{NetworkSettingsBase:{Bridge: SandboxID:9c3cfc54b8e53e06be36d20ad521caab153034a4f708abab0672496c1c36f4ef SandboxKey:/var/run/docker/netns/9c3cfc54b8e5 Ports:map[4242/tcp:[{HostIP:0.0.0.0 HostPort:52852}]] HairpinMode:false LinkLocalIPv6Address: LinkLocalIPv6PrefixLen:0 SecondaryIPAddresses:[] SecondaryIPv6Addresses:[]} DefaultNetworkSettings:{EndpointID:2d5a0b8307b28f27c51ef0d162a24bbdb1ec61f9078daa253335cd51726633e9 Gateway:172.17.0.1 GlobalIPv6Address: GlobalIPv6PrefixLen:0 IPAddress:172.17.0.5 IPPrefixLen:16 IPv6Gateway: MacAddress:redacted} Networks:map[bridge:0x1400018ed20]}
+&{Hostname:f5fee6be5cc8 Domainname: User:rstudio-pm AttachStdin:false AttachStdout:false AttachStderr:false ExposedPorts:map[4242/tcp:{}] Tty:false OpenStdin:false StdinOnce:false Env:[] Cmd:[bash -c sleep 1 && /usr/local/bin/startup.sh] Healthcheck:<nil> ArgsEscaped:false Image:posit/package-manager:development Volumes:map[] WorkingDir: Entrypoint:[tini --] NetworkDisabled:false MacAddress: OnBuild:[] Labels:map[] StopSignal: StopTimeout:<nil> Shell:[]}

Where sometimes the external port is available Ports:map[4242/tcp:[{HostIP:0.0.0.0 HostPort:52852}]] and othertimes it is not Ports:map[4242/tcp:[]] (note that I stripped some internal details and there a 3 similar containers starting up)

[mdelapenya]

Mmmm those logs makes me think the inspect is not caching the calls 🤔 let me take a look on that

[mdelapenya]

By the way @tylfin could you share your docker info? I'd like to understand if you are on Podman, Docker or any other container runtime.

[tylfin]

Sure thing, I'm using docker-for-mac on an M1 laptop, docker info attached

docker-info.txt

[tylfin]

I was finally able to create a minimal reproduction, and realized this lifecycle hook is the cause:

	req.LifecycleHooks = append(req.LifecycleHooks, testcontainers.ContainerLifecycleHooks{
		PostStarts: []testcontainers.ContainerHook{
			func(ctx context.Context, c testcontainers.Container) error {
				_, err := c.MappedPort(ctx, nat.Port("80/tcp"))
				if err != nil {
					return err
				}
				// Logging of port information...
				return nil
			},
		},
	})

When I switched it to PostReadies it works fine. I don't know if PostStarts should have this information, but this workaround is good for me.

[eddumelendez]

I don't think the postStarts would be the right place to call the mapped port because there is no signal that the service has started. PostReadies is the right place.

[mdelapenya]

I don't think the postStarts would be the right place to call the mapped port because there is no signal that the service has started. PostReadies is the right place.

Exactly, the PostReadies happens right after the wait strategies, which is more consistent regarding availability of the service. The PostStarts hook does not guarantee the readiness, just that the container started.

[tylfin]

Alright, I'm going to go ahead and close this