From ce70345157c558047193edfe71d1a07c41e6ba89 Mon Sep 17 00:00:00 2001 From: Steven Hartland Date: Tue, 30 Jul 2024 12:57:02 +0100 Subject: [PATCH] debugging: extract to single location Extract the majority of the debugging to debug.go. --- debug.go | 225 ++++++++++++++++++++++++++++ docker.go | 44 +++--- docker_test.go | 212 ++------------------------ lifecycle.go | 8 +- modules/compose/compose_api.go | 5 +- modules/compose/compose_api_test.go | 139 +---------------- 6 files changed, 266 insertions(+), 367 deletions(-) create mode 100644 debug.go diff --git a/debug.go b/debug.go new file mode 100644 index 00000000000..18783bebe62 --- /dev/null +++ b/debug.go @@ -0,0 +1,225 @@ +package testcontainers + +import ( + "context" + "encoding/json" + "os" + "os/exec" + "strings" + "testing" + "time" + + "github.com/testcontainers/testcontainers-go/internal/config" + "github.com/testcontainers/testcontainers-go/internal/core" +) + +// testLogConsumer is a testcontainers LogConsumer and io.Writer +// that writes to the test log. +type testLogConsumer struct { + t *testing.T +} + +// NewTestLogConsumer creates a new Logger for t. +func NewTestLogConsumer(t *testing.T) *testLogConsumer { + t.Helper() + return &testLogConsumer{t: t} +} + +// Accept implements LogConsumer. +func (l *testLogConsumer) Accept(log Log) { + l.t.Log(time.Now().Format(time.RFC3339Nano) + ": " + log.LogType + ": " + strings.TrimSpace(string(log.Content))) +} + +// Write implements io.Write. +func (l *testLogConsumer) Write(p []byte) (int, error) { + l.t.Log(time.Now().Format(time.RFC3339Nano) + ": " + strings.TrimSpace(string(p))) + return len(p), nil +} + +var debugEnabledTime time.Time + +// DebugTest applies debugging to t which: +// - Logs reaper container output to the test. +// - Enables docker debugging and outputs the docker daemon logs before and after the test to the test. +func DebugTest(t *testing.T) { + t.Helper() + config.Reset() + // t.Setenv("TESTCONTAINERS_RYUK_DISABLED", "true") + t.Setenv("TESTCONTAINERS_RYUK_VERBOSE", "true") + + oldDebugPrintln := DebugPrintln + DebugPrintln = func(a ...any) { + t.Log(append([]any{time.Now().Format(time.RFC3339Nano)}, a...)...) + } + t.Cleanup(func() { + DebugPrintln = oldDebugPrintln + config.Reset() + }) + + // Stream reaper logs + container, err := spawner.lookupContainer(context.Background(), core.SessionID()) + if err != nil { + t.Logf("look up container: %s", err) + return + } + + log := NewTestLogConsumer(t) + timeout := time.Hour + container.logProductionTimeout = &timeout + container.logProductionCtx, container.logProductionCancel = context.WithCancelCause(context.Background()) + t.Cleanup(func() { + container.logProductionCancel(errLogProductionStop) + }) + + go func() { + if err := container.logProducer(log, log); err != nil { + t.Logf("error running logProducer: %s", err) + } + }() + + DebugDocker(t, true) + + t.Cleanup(func() { + DebugDocker(t, false) + }) +} + +// Docker enables or disables Docker debug logging and outputs +// the logs to t before and after the test so there is a full trace +// of the docker actions performed. +func DebugDocker(t *testing.T, enable bool) { + t.Helper() + + t.Log("Docker debug logging:", enable) + + const file = "/etc/docker/daemon.json" + data, err := os.ReadFile(file) + if err != nil { + t.Logf("error reading daemon.json: %s", err) + return + } + + t.Logf("daemon.json: %s", string(data)) + + cfg := make(map[string]any) + err = json.Unmarshal(data, &cfg) + if err != nil { + t.Logf("error unmarshalling daemon.json: %s", err) + return + } + + cfg["debug"] = enable + + data, err = json.Marshal(cfg) + if err != nil { + t.Logf("error marshalling daemon.json: %s", err) + return + } + + t.Logf("daemon.json: %s", string(data)) + + f, err := os.CreateTemp("", "") + if err != nil { + t.Logf("error writing daemon.json: %s", err) + return + } + + defer os.Remove(f.Name()) + + if _, err := f.Write(data); err != nil { + t.Logf("error writing daemon.json: %s", err) + return + } + + cmd := exec.CommandContext(context.Background(), "sudo", "cp", f.Name(), file) + log, err := cmd.CombinedOutput() + if err != nil { + t.Logf("error restarting docker: %s, %s", err, log) + return + } + + if enable { + debugEnabledTime = time.Now() + } + cmd = exec.CommandContext(context.Background(), "sudo", "systemctl", "reload-or-restart", "docker") + log, err = cmd.CombinedOutput() + if err != nil { + t.Logf("error reloading docker: %s, %s", err, log) + cmd = exec.CommandContext(context.Background(), "journalctl", "-xeu", "docker.service") + log, err = cmd.CombinedOutput() + if err != nil { + t.Logf("error running journalctl: %s, %s", err, log) + return + } + t.Logf("docker journalctl: %s", log) + return + } + + t.Logf("docker reloaded: %s", log) +} + +// DebugContainerFilter returns a filter for the given container. +func DebugContainerFilter(container Container) []string { + return []string{ + "type=container", + "container=" + container.GetContainerID(), + } +} + +// DebugInfo details of the following to the test log: +// - Docker events for the container. +// - Docker version and info. +// - Docker logs if docker debugging is enabled. +func DebugInfo(t *testing.T, filter ...string) { + t.Helper() + + // Docker events. + time.Sleep(time.Second) // Events are not immediately available. + args := []string{"events"} + for _, v := range filter { + args = append(args, "--filter", v) + } + args = append(args, "--since", "10m", "--until", "0s") + cmd := exec.CommandContext(context.Background(), "docker", args...) + stdoutStderr, err := cmd.CombinedOutput() + if err != nil { + t.Logf("error running docker events: %s", err) + } else { + t.Logf("docker events: %s", stdoutStderr) + } + + // Docker version. + cmd = exec.CommandContext(context.Background(), "docker", "version") + stdoutStderr, err = cmd.CombinedOutput() + if err != nil { + t.Logf("error running docker version: %s", err) + } else { + t.Logf("docker version: %s", stdoutStderr) + } + + // Docker info. + cmd = exec.CommandContext(context.Background(), "docker", "info") + stdoutStderr, err = cmd.CombinedOutput() + if err != nil { + t.Logf("error running docker info: %s", err) + } else { + t.Logf("docker info: %s", stdoutStderr) + } + + // Docker logs. + if debugEnabledTime.IsZero() { + t.Log("debugEnabledTime is zero, skipping journalctl") + } else { + cmd = exec.CommandContext(context.Background(), + "journalctl", "-xu", "docker.service", + "--since", debugEnabledTime.Format("2006-01-02 15:04:05"), + ) + stdoutStderr, err = cmd.CombinedOutput() + if err != nil { + t.Logf("error running journalctl: %s, %s", err, stdoutStderr) + } else { + t.Logf("docker journalctl: %s", stdoutStderr) + } + debugEnabledTime = time.Time{} + } +} diff --git a/docker.go b/docker.go index fcf66cb790a..b33bf850801 100644 --- a/docker.go +++ b/docker.go @@ -268,10 +268,10 @@ func (c *DockerContainer) Stop(ctx context.Context, timeout *time.Duration) erro // without exposing the ability to fully initialize the container state. // See: https://github.com/testcontainers/testcontainers-go/issues/2667 // TODO: Add a check for isRunning when the above issue is resolved. - debugPrintln("XXX: DockerContainer.Stop", c.ID) + DebugPrintln("XXX: DockerContainer.Stop", c.ID) err := c.stoppingHook(ctx) if err != nil { - debugPrintln("XXX: DockerContainer.Stop stoppingHook error:", err, c.ID) + DebugPrintln("XXX: DockerContainer.Stop stoppingHook error:", err, c.ID) return fmt.Errorf("stopping hook: %w", err) } @@ -282,9 +282,9 @@ func (c *DockerContainer) Stop(ctx context.Context, timeout *time.Duration) erro options.Timeout = &timeoutSeconds } - debugPrintln("XXX: DockerContainer.Stop ContainerStop", c.ID) + DebugPrintln("XXX: DockerContainer.Stop ContainerStop", c.ID) if err := c.provider.client.ContainerStop(ctx, c.ID, options); err != nil { - debugPrintln("XXX: DockerContainer.Stop ContainerStop error:", err) + DebugPrintln("XXX: DockerContainer.Stop ContainerStop error:", err) return fmt.Errorf("container stop: %w", err) } @@ -297,10 +297,10 @@ func (c *DockerContainer) Stop(ctx context.Context, timeout *time.Duration) erro err = c.stoppedHook(ctx) if err != nil { - debugPrintln("XXX: DockerContainer.Stop stoppedHook error:", err, c.ID) + DebugPrintln("XXX: DockerContainer.Stop stoppedHook error:", err, c.ID) return fmt.Errorf("stopped hook: %w", err) } - debugPrintln("XXX: DockerContainer.Stop done", c.ID) + DebugPrintln("XXX: DockerContainer.Stop done", c.ID) return nil } @@ -317,7 +317,7 @@ func (c *DockerContainer) Terminate(ctx context.Context) error { // to ensure that child containers are stopped so we manually call stop. // TODO: make this configurable via a functional option. // time.Sleep(10 * time.Millisecond) - debugPrintln("XXX: DockerContainer.Terminate", c.ID) + DebugPrintln("XXX: DockerContainer.Terminate", c.ID) timeout := 10 * time.Second err := c.Stop(ctx, &timeout) @@ -342,12 +342,12 @@ func (c *DockerContainer) Terminate(ctx context.Context) error { errs := []error{c.terminatingHook(ctx)} // time.Sleep(10 * time.Millisecond) - debugPrintln("XXX: DockerContainer.ContainerRemove", c.ID) + DebugPrintln("XXX: DockerContainer.ContainerRemove", c.ID) err = c.provider.client.ContainerRemove(ctx, c.GetContainerID(), container.RemoveOptions{ RemoveVolumes: true, Force: true, }) - debugPrintln("XXX: DockerContainer.ContainerRemove done", c.ID, err) + DebugPrintln("XXX: DockerContainer.ContainerRemove done", c.ID, err) errs = append(errs, err, c.terminatedHook(ctx)) if c.imageWasBuilt && !c.keepBuiltImage { @@ -759,7 +759,7 @@ func (c *DockerContainer) StartLogProducer(ctx context.Context, opts ...LogProdu // Use functional option WithLogProductionTimeout() to override default timeout. If it's // lower than 5s and greater than 60s it will be set to 5s or 60s respectively. func (c *DockerContainer) startLogProduction(ctx context.Context, opts ...LogProductionOption) error { - debugPrintln("XXX: DockerContainer.startLogProduction", c.ID) + DebugPrintln("XXX: DockerContainer.startLogProduction", c.ID) for _, opt := range opts { opt(c) } @@ -795,8 +795,8 @@ func (c *DockerContainer) startLogProduction(ctx context.Context, opts ...LogPro // - A fatal error occurs // - No more logs are available func (c *DockerContainer) logProducer(stdout, stderr io.Writer) error { - debugPrintln("XXX: DockerContainer.startLogProduction go", c.ID) - defer debugPrintln("XXX: DockerContainer.startLogProduction done", c.ID) + DebugPrintln("XXX: DockerContainer.startLogProduction go", c.ID) + defer DebugPrintln("XXX: DockerContainer.startLogProduction done", c.ID) // Clean up idle client connections. defer c.provider.Close() @@ -813,7 +813,7 @@ func (c *DockerContainer) logProducer(stdout, stderr io.Writer) error { defer cancel() err := c.copyLogs(timeoutCtx, options, stdout, stderr) - debugPrintln("XXX: DockerContainer.logProducerSince:", err, c.ID) + DebugPrintln("XXX: DockerContainer.logProducerSince:", err, c.ID) switch { case err == nil: // No more logs available. @@ -827,7 +827,7 @@ func (c *DockerContainer) logProducer(stdout, stderr io.Writer) error { // Unexpected error, retry. Logger.Printf("Unexpected error reading logs: %v", err) } - debugPrintln("XXX: DockerContainer.logProducerAll:", err, c.ID) + DebugPrintln("XXX: DockerContainer.logProducerAll:", err, c.ID) // Retry from the last log received. now := time.Now() @@ -839,13 +839,13 @@ func (c *DockerContainer) logProducer(stdout, stderr io.Writer) error { func (c *DockerContainer) copyLogs(ctx context.Context, options container.LogsOptions, stdout, stderr io.Writer) error { rc, err := c.provider.client.ContainerLogs(ctx, c.GetContainerID(), options) if err != nil { - debugPrintln("XXX: DockerContainer.startLogProduction ContainerLogs:", err) + DebugPrintln("XXX: DockerContainer.startLogProduction ContainerLogs:", err) return fmt.Errorf("container logs: %w", err) } defer rc.Close() if _, err = stdcopy.StdCopy(stdout, stderr, rc); err != nil { - debugPrintln("XXX: DockerContainer.startLogProduction stdcopy.StdCopy:", err) + DebugPrintln("XXX: DockerContainer.startLogProduction stdcopy.StdCopy:", err) return fmt.Errorf("stdcopy: %w", err) } @@ -857,13 +857,13 @@ func (c *DockerContainer) StopLogProducer() error { return c.stopLogProduction() } -// debugPrintln is a function that can be overridden for debugging purposes. -var debugPrintln = func(a ...any) {} +// DebugPrintln is a function that can be overridden for debugging purposes. +var DebugPrintln = func(a ...any) {} // stopLogProduction will stop the concurrent process that is reading logs // and sending them to each added LogConsumer func (c *DockerContainer) stopLogProduction() error { - debugPrintln("XXX: DockerContainer.stopLogProduction", c.ID) + DebugPrintln("XXX: DockerContainer.stopLogProduction", c.ID) if c.logProductionCancel == nil { return nil @@ -872,10 +872,10 @@ func (c *DockerContainer) stopLogProduction() error { // Signal the log production to stop. c.logProductionCancel(errLogProductionStop) - debugPrintln("XXX: DockerContainer.stopLogProduction signalled", c.ID) + DebugPrintln("XXX: DockerContainer.stopLogProduction signalled", c.ID) if err := context.Cause(c.logProductionCtx); err != nil { - debugPrintln("XXX: DockerContainer.stopLogProduction err:", err, c.ID) + DebugPrintln("XXX: DockerContainer.stopLogProduction err:", err, c.ID) switch { case errors.Is(err, errLogProductionStop): // Log production was stopped. @@ -889,7 +889,7 @@ func (c *DockerContainer) stopLogProduction() error { } } - debugPrintln("XXX: DockerContainer.stopLogProduction done", c.ID) + DebugPrintln("XXX: DockerContainer.stopLogProduction done", c.ID) return nil } diff --git a/docker_test.go b/docker_test.go index 243b9557cba..6254a7241be 100644 --- a/docker_test.go +++ b/docker_test.go @@ -3,7 +3,6 @@ package testcontainers import ( "bytes" "context" - "encoding/json" "errors" "fmt" "io" @@ -11,7 +10,6 @@ import ( "math/rand" "net/http" "os" - "os/exec" "path/filepath" "regexp" "strings" @@ -27,8 +25,6 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "github.com/testcontainers/testcontainers-go/internal/config" - "github.com/testcontainers/testcontainers-go/internal/core" "github.com/testcontainers/testcontainers-go/wait" ) @@ -244,141 +240,11 @@ func TestContainerReturnItsContainerID(t *testing.T) { } } -type logger struct { - t *testing.T -} - -func (l *logger) Accept(log Log) { - l.t.Log(time.Now().Format(time.RFC3339Nano) + ": " + log.LogType + ": " + strings.TrimSpace(string(log.Content))) -} - -func (l *logger) Write(p []byte) (int, error) { - l.t.Log(time.Now().Format(time.RFC3339Nano) + ": " + strings.TrimSpace(string(p))) - return len(p), nil -} - -var debugEnabledTime time.Time - -func debugTest(t *testing.T) { - t.Helper() - config.Reset() - // t.Setenv("TESTCONTAINERS_RYUK_DISABLED", "true") - t.Setenv("TESTCONTAINERS_RYUK_VERBOSE", "true") - - oldDebugPrintln := debugPrintln - debugPrintln = func(a ...any) { - t.Log(append([]any{time.Now().Format(time.RFC3339Nano)}, a...)...) - } - t.Cleanup(func() { - debugPrintln = oldDebugPrintln - config.Reset() - }) - - // Stream reaper logs - container, err := spawner.lookupContainer(context.Background(), core.SessionID()) - if err != nil { - t.Logf("look up container: %s", err) - return - } - - log := &logger{t: t} - timeout := time.Hour - container.logProductionTimeout = &timeout - container.logProductionCtx, container.logProductionCancel = context.WithCancelCause(context.Background()) - t.Cleanup(func() { - container.logProductionCancel(errLogProductionStop) - }) - - go func() { - if err := container.logProducer(log, log); err != nil { - t.Logf("error running logProducer: %s", err) - } - }() - - dockerDebugging(t, true) - - t.Cleanup(func() { - dockerDebugging(t, false) - }) -} - -// dockerDebugging enables or disables Docker debug logging. -func dockerDebugging(t *testing.T, enable bool) { - t.Helper() - - t.Log("Docker debug logging:", enable) - - const file = "/etc/docker/daemon.json" - data, err := os.ReadFile(file) - if err != nil { - t.Logf("error reading daemon.json: %s", err) - return - } - - t.Logf("daemon.json: %s", string(data)) - - cfg := make(map[string]any) - err = json.Unmarshal(data, &cfg) - if err != nil { - t.Logf("error unmarshalling daemon.json: %s", err) - return - } - - cfg["debug"] = enable - - data, err = json.Marshal(cfg) - if err != nil { - t.Logf("error marshalling daemon.json: %s", err) - return - } - - t.Logf("daemon.json: %s", string(data)) - - f, err := os.CreateTemp("", "") - if err != nil { - t.Logf("error writing daemon.json: %s", err) - return - } - - defer os.Remove(f.Name()) - - if _, err := f.Write(data); err != nil { - t.Logf("error writing daemon.json: %s", err) - return - } - - cmd := exec.CommandContext(context.Background(), "sudo", "cp", f.Name(), file) - log, err := cmd.CombinedOutput() - if err != nil { - t.Logf("error restarting docker: %s, %s", err, log) - return - } - - if enable { - debugEnabledTime = time.Now() - } - cmd = exec.CommandContext(context.Background(), "sudo", "systemctl", "reload-or-restart", "docker") - log, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error reloading docker: %s, %s", err, log) - cmd = exec.CommandContext(context.Background(), "journalctl", "-xeu", "docker.service") - log, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error running journalctl: %s, %s", err, log) - return - } - t.Logf("docker journalctl: %s", log) - return - } - - t.Logf("docker reloaded: %s", log) -} - func TestContainerTerminationResetsState(t *testing.T) { ctx := context.Background() // Does this fix the flaky test? - debugTest(t) + DebugTest(t) nginxA, err := GenericContainer(ctx, GenericContainerRequest{ ProviderType: providerType, @@ -388,7 +254,7 @@ func TestContainerTerminationResetsState(t *testing.T) { nginxDefaultPort, }, LogConsumerCfg: &LogConsumerConfig{ - Consumers: []LogConsumer{&logger{t: t}}, + Consumers: []LogConsumer{NewTestLogConsumer(t)}, }, }, Started: true, @@ -398,7 +264,7 @@ func TestContainerTerminationResetsState(t *testing.T) { t.Logf("started: %s", nginxA.GetContainerID()) t.Cleanup(func() { - debugContainer(t, nginxA) + DebugInfo(t, DebugContainerFilter(nginxA)...) }) err = nginxA.Terminate(ctx) @@ -411,60 +277,6 @@ func TestContainerTerminationResetsState(t *testing.T) { require.Nil(t, inspect) } -func debugContainer(t *testing.T, container Container) { - t.Helper() - - // Docker events. - time.Sleep(time.Second) // Events are not immediately available. - cmd := exec.CommandContext(context.Background(), - "docker", "events", - "--filter", "type=container", - "--filter", "container="+container.GetContainerID(), - "--since", "10m", - "--until", "0s", - ) - stdoutStderr, err := cmd.CombinedOutput() - if err != nil { - t.Logf("error running docker events: %s", err) - } else { - t.Logf("docker events: %s", stdoutStderr) - } - - // Docker version. - cmd = exec.CommandContext(context.Background(), "docker", "version") - stdoutStderr, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error running docker version: %s", err) - } else { - t.Logf("docker version: %s", stdoutStderr) - } - - // Docker info. - cmd = exec.CommandContext(context.Background(), "docker", "info") - stdoutStderr, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error running docker info: %s", err) - } else { - t.Logf("docker info: %s", stdoutStderr) - } - - // Docker logs. - if debugEnabledTime.IsZero() { - t.Log("debugEnabledTime is zero, skipping journalctl") - } else { - cmd = exec.CommandContext(context.Background(), - "journalctl", "-xu", "docker.service", - "--since", debugEnabledTime.Format("2006-01-02 15:04:05"), - ) - stdoutStderr, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error running journalctl: %s, %s", err, stdoutStderr) - } else { - t.Logf("docker journalctl: %s", stdoutStderr) - } - } -} - func TestContainerStateAfterTermination(t *testing.T) { createContainerFn := func(ctx context.Context, t *testing.T) (Container, error) { return GenericContainer(ctx, GenericContainerRequest{ @@ -475,7 +287,7 @@ func TestContainerStateAfterTermination(t *testing.T) { nginxDefaultPort, }, LogConsumerCfg: &LogConsumerConfig{ - Consumers: []LogConsumer{&logger{t: t}}, + Consumers: []LogConsumer{NewTestLogConsumer(t)}, }, }, Started: true, @@ -483,7 +295,7 @@ func TestContainerStateAfterTermination(t *testing.T) { } // Does this fix the flaky test? - debugTest(t) + DebugTest(t) t.Run("Nil State after termination", func(t *testing.T) { ctx := context.Background() @@ -491,7 +303,7 @@ func TestContainerStateAfterTermination(t *testing.T) { CleanupContainer(t, nginx) require.NoError(t, err) t.Cleanup(func() { - debugContainer(t, nginx) + DebugInfo(t, DebugContainerFilter(nginx)...) }) // terminate the container before the raw state is set @@ -510,7 +322,7 @@ func TestContainerStateAfterTermination(t *testing.T) { CleanupContainer(t, nginx) require.NoError(t, err) t.Cleanup(func() { - debugContainer(t, nginx) + DebugInfo(t, DebugContainerFilter(nginx)...) }) state, err := nginx.State(ctx) @@ -529,7 +341,7 @@ func TestContainerStateAfterTermination(t *testing.T) { func TestContainerTerminationRemovesDockerImage(t *testing.T) { // Does this fix the flaky test? - debugTest(t) + DebugTest(t) t.Run("if not built from Dockerfile", func(t *testing.T) { ctx := context.Background() @@ -547,7 +359,7 @@ func TestContainerTerminationRemovesDockerImage(t *testing.T) { nginxDefaultPort, }, LogConsumerCfg: &LogConsumerConfig{ - Consumers: []LogConsumer{&logger{t: t}}, + Consumers: []LogConsumer{NewTestLogConsumer(t)}, }, }, Started: true, @@ -555,7 +367,7 @@ func TestContainerTerminationRemovesDockerImage(t *testing.T) { CleanupContainer(t, ctr) require.NoError(t, err) t.Cleanup(func() { - debugContainer(t, ctr) + DebugInfo(t, DebugContainerFilter(ctr)...) }) err = ctr.Terminate(ctx) @@ -582,7 +394,7 @@ func TestContainerTerminationRemovesDockerImage(t *testing.T) { ExposedPorts: []string{"6379/tcp"}, WaitingFor: wait.ForLog("Ready to accept connections"), LogConsumerCfg: &LogConsumerConfig{ - Consumers: []LogConsumer{&logger{t: t}}, + Consumers: []LogConsumer{NewTestLogConsumer(t)}, }, } ctr, err := GenericContainer(ctx, GenericContainerRequest{ @@ -601,7 +413,7 @@ func TestContainerTerminationRemovesDockerImage(t *testing.T) { } imageID := resp.Config.Image t.Cleanup(func() { - debugContainer(t, ctr) + DebugInfo(t, DebugContainerFilter(ctr)...) }) err = ctr.Terminate(ctx) diff --git a/lifecycle.go b/lifecycle.go index 5c73b3853ac..5fb2ed4f3e8 100644 --- a/lifecycle.go +++ b/lifecycle.go @@ -169,7 +169,7 @@ var defaultLogConsumersHook = func(cfg *LogConsumerConfig) ContainerLifecycleHoo // See combineContainerHooks for the order of execution. func(ctx context.Context, c Container) error { if cfg == nil || len(cfg.Consumers) == 0 { - debugPrintln("XXX: PostStarts - no consumers", c.GetContainerID()) + DebugPrintln("XXX: PostStarts - no consumers", c.GetContainerID()) return nil } @@ -179,7 +179,7 @@ var defaultLogConsumersHook = func(cfg *LogConsumerConfig) ContainerLifecycleHoo dockerContainer.followOutput(consumer) } - debugPrintln("XXX: PostStarts - consumers:", len(dockerContainer.consumers), c.GetContainerID()) + DebugPrintln("XXX: PostStarts - consumers:", len(dockerContainer.consumers), c.GetContainerID()) return dockerContainer.startLogProduction(ctx, cfg.Opts...) }, }, @@ -188,12 +188,12 @@ var defaultLogConsumersHook = func(cfg *LogConsumerConfig) ContainerLifecycleHoo // See combineContainerHooks for the order of execution. func(ctx context.Context, c Container) error { if cfg == nil || len(cfg.Consumers) == 0 { - debugPrintln("XXX: PostStops - no consumers", c.GetContainerID()) + DebugPrintln("XXX: PostStops - no consumers", c.GetContainerID()) return nil } dockerContainer := c.(*DockerContainer) - debugPrintln("XXX: PostStops - consumers:", len(dockerContainer.consumers), c.GetContainerID()) + DebugPrintln("XXX: PostStops - consumers:", len(dockerContainer.consumers), c.GetContainerID()) return dockerContainer.stopLogProduction() }, }, diff --git a/modules/compose/compose_api.go b/modules/compose/compose_api.go index 1299ff6a8fb..cb6d61cf669 100644 --- a/modules/compose/compose_api.go +++ b/modules/compose/compose_api.go @@ -257,9 +257,6 @@ func (d *dockerCompose) Down(ctx context.Context, opts ...StackDownOption) error return d.composeService.Down(ctx, d.name, options.DownOptions) } -// debugPrintln is a function that can be overridden for debugging purposes. -var debugPrintln = func(a ...any) {} - func (d *dockerCompose) Up(ctx context.Context, opts ...StackUpOption) (err error) { d.lock.Lock() defer d.lock.Unlock() @@ -351,7 +348,7 @@ func (d *dockerCompose) Up(ctx context.Context, opts ...StackUpOption) (err erro return } - debugPrintln("XXX: Triggering cleanup", len(termSignals)) + testcontainers.DebugPrintln("XXX: Triggering cleanup", len(termSignals)) for _, ts := range termSignals { ts <- true } diff --git a/modules/compose/compose_api_test.go b/modules/compose/compose_api_test.go index 41426d6e2f0..b7f82d22e3f 100644 --- a/modules/compose/compose_api_test.go +++ b/modules/compose/compose_api_test.go @@ -2,11 +2,9 @@ package compose import ( "context" - "encoding/json" "fmt" "hash/fnv" "os" - "os/exec" "path/filepath" "strings" "testing" @@ -60,7 +58,7 @@ func TestDockerComposeAPIStrategyForInvalidService(t *testing.T) { } func TestDockerComposeAPIWithWaitLogStrategy(t *testing.T) { - debugTest(t) + testcontainers.DebugTest(t) path, _ := RenderComposeComplex(t) compose, err := NewDockerCompose(path) @@ -70,7 +68,7 @@ func TestDockerComposeAPIWithWaitLogStrategy(t *testing.T) { t.Cleanup(cancel) t.Cleanup(func() { - debugContainer(t, "api-mysql") + testcontainers.DebugInfo(t) }) err = compose. @@ -655,136 +653,3 @@ func cleanup(t *testing.T, compose *dockerCompose) { ), "compose.Down()") }) } - -var debugEnabledTime time.Time - -func debugTest(t *testing.T) { - t.Helper() - config.Reset() - // t.Setenv("TESTCONTAINERS_RYUK_DISABLED", "true") - t.Setenv("TESTCONTAINERS_RYUK_VERBOSE", "true") - - oldDebugPrintln := debugPrintln - debugPrintln = func(a ...any) { - t.Log(append([]any{time.Now().Format(time.RFC3339Nano)}, a...)...) - } - t.Cleanup(func() { - debugPrintln = oldDebugPrintln - config.Reset() - }) - - dockerDebugging(t, true) - - t.Cleanup(func() { - dockerDebugging(t, false) - }) -} - -// dockerDebugging enables or disables Docker debug logging. -func dockerDebugging(t *testing.T, enable bool) { - t.Helper() - - t.Log("Docker debug logging:", enable) - - const file = "/etc/docker/daemon.json" - data, err := os.ReadFile(file) - if err != nil { - t.Logf("error reading daemon.json: %s", err) - return - } - - t.Logf("daemon.json: %s", string(data)) - - cfg := make(map[string]any) - err = json.Unmarshal(data, &cfg) - if err != nil { - t.Logf("error unmarshalling daemon.json: %s", err) - return - } - - cfg["debug"] = enable - - data, err = json.Marshal(cfg) - if err != nil { - t.Logf("error marshalling daemon.json: %s", err) - return - } - - t.Logf("daemon.json: %s", string(data)) - - f, err := os.CreateTemp("", "") - if err != nil { - t.Logf("error writing daemon.json: %s", err) - return - } - - defer os.Remove(f.Name()) - - if _, err := f.Write(data); err != nil { - t.Logf("error writing daemon.json: %s", err) - return - } - - cmd := exec.CommandContext(context.Background(), "sudo", "cp", f.Name(), file) - log, err := cmd.CombinedOutput() - if err != nil { - t.Logf("error restarting docker: %s, %s", err, log) - return - } - - if enable { - debugEnabledTime = time.Now() - } - cmd = exec.CommandContext(context.Background(), "sudo", "systemctl", "reload-or-restart", "docker") - log, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error reloading docker: %s, %s", err, log) - cmd = exec.CommandContext(context.Background(), "journalctl", "-xeu", "docker.service") - log, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error running journalctl: %s, %s", err, log) - return - } - t.Logf("docker journalctl: %s", log) - return - } - - t.Logf("docker reloaded: %s", log) -} - -func debugContainer(t *testing.T, service string) { - t.Helper() - - // Docker events. - time.Sleep(time.Second) // Events are not immediately available. - cmd := exec.CommandContext(context.Background(), - "docker", "events", - // "--filter", "type=container", - // "--filter", "service="+service, - "--since", "10m", - "--until", "0s", - ) - _ = service - stdoutStderr, err := cmd.CombinedOutput() - if err != nil { - t.Logf("error running docker events: %s", err) - } else { - t.Logf("docker events: %s", stdoutStderr) - } - - // Docker logs. - if debugEnabledTime.IsZero() { - t.Log("debugEnabledTime is zero, skipping journalctl") - } else { - cmd = exec.CommandContext(context.Background(), - "journalctl", "-xu", "docker.service", - "--since", debugEnabledTime.Format("2006-01-02 15:04:05"), - ) - stdoutStderr, err = cmd.CombinedOutput() - if err != nil { - t.Logf("error running journalctl: %s, %s", err, stdoutStderr) - } else { - t.Logf("docker journalctl: %s", stdoutStderr) - } - } -}