Skip to content

Commit

Permalink
debugging: extract to single location
Browse files Browse the repository at this point in the history
Extract the majority of the debugging to debug.go.
  • Loading branch information
stevenh committed Jul 30, 2024
1 parent 7426150 commit ce70345
Show file tree
Hide file tree
Showing 6 changed files with 266 additions and 367 deletions.
225 changes: 225 additions & 0 deletions debug.go
Original file line number Diff line number Diff line change
@@ -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{}
}
}
44 changes: 22 additions & 22 deletions docker.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}

Expand All @@ -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)
}

Expand All @@ -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
}
Expand All @@ -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)
Expand All @@ -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 {
Expand Down Expand Up @@ -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)
}
Expand Down Expand Up @@ -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()
Expand All @@ -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.
Expand All @@ -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()
Expand All @@ -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)
}

Expand All @@ -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
Expand All @@ -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.
Expand All @@ -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
}

Expand Down
Loading

0 comments on commit ce70345

Please sign in to comment.