docker_cli_logs_test.go

package main

import (
	"fmt"
	"os/exec"
	"regexp"
	"strings"
	"testing"
	"time"

	"github.com/docker/docker/pkg/timeutils"
)

// This used to work, it test a log of PageSize-1 (gh#4851)
func TestLogsContainerSmallerThanPage(t *testing.T) {
	testLen := 32767
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen))
	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	if len(out) != testLen+1 {
		t.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out))
	}

	deleteContainer(cleanedContainerID)

	logDone("logs - logs container running echo smaller than page size")
}

// Regression test: When going over the PageSize, it used to panic (gh#4851)
func TestLogsContainerBiggerThanPage(t *testing.T) {
	testLen := 32768
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen))
	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	if len(out) != testLen+1 {
		t.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out))
	}

	deleteContainer(cleanedContainerID)

	logDone("logs - logs container running echo bigger than page size")
}

// Regression test: When going much over the PageSize, it used to block (gh#4851)
func TestLogsContainerMuchBiggerThanPage(t *testing.T) {
	testLen := 33000
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen))
	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	if len(out) != testLen+1 {
		t.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out))
	}

	deleteContainer(cleanedContainerID)

	logDone("logs - logs container running echo much bigger than page size")
}

func TestLogsTimestamps(t *testing.T) {
	testLen := 100
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen))

	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", "-t", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	lines := strings.Split(out, "\n")

	if len(lines) != testLen+1 {
		t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
	}

	ts := regexp.MustCompile(`^.* `)

	for _, l := range lines {
		if l != "" {
			_, err := time.Parse(timeutils.RFC3339NanoFixed+" ", ts.FindString(l))
			if err != nil {
				t.Fatalf("Failed to parse timestamp from %v: %v", l, err)
			}
			if l[29] != 'Z' { // ensure we have padded 0's
				t.Fatalf("Timestamp isn't padded properly: %s", l)
			}
		}
	}

	deleteContainer(cleanedContainerID)

	logDone("logs - logs with timestamps")
}

func TestLogsSeparateStderr(t *testing.T) {
	msg := "stderr_log"
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg))

	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID)
	stdout, stderr, _, err := runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	if stdout != "" {
		t.Fatalf("Expected empty stdout stream, got %v", stdout)
	}

	stderr = strings.TrimSpace(stderr)
	if stderr != msg {
		t.Fatalf("Expected %v in stderr stream, got %v", msg, stderr)
	}

	deleteContainer(cleanedContainerID)

	logDone("logs - separate stderr (without pseudo-tty)")
}

func TestLogsStderrInStdout(t *testing.T) {
	msg := "stderr_log"
	runCmd := exec.Command(dockerBinary, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg))

	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID)
	stdout, stderr, _, err := runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	if stderr != "" {
		t.Fatalf("Expected empty stderr stream, got %v", stdout)
	}

	stdout = strings.TrimSpace(stdout)
	if stdout != msg {
		t.Fatalf("Expected %v in stdout stream, got %v", msg, stdout)
	}

	deleteContainer(cleanedContainerID)

	logDone("logs - stderr in stdout (with pseudo-tty)")
}

func TestLogsTail(t *testing.T) {
	testLen := 100
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen))

	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", "--tail", "5", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	lines := strings.Split(out, "\n")

	if len(lines) != 6 {
		t.Fatalf("Expected log %d lines, received %d\n", 6, len(lines))
	}

	logsCmd = exec.Command(dockerBinary, "logs", "--tail", "all", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	lines = strings.Split(out, "\n")

	if len(lines) != testLen+1 {
		t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
	}

	logsCmd = exec.Command(dockerBinary, "logs", "--tail", "random", cleanedContainerID)
	out, _, _, err = runCommandWithStdoutStderr(logsCmd)
	if err != nil {
		t.Fatalf("failed to log container: %s, %v", out, err)
	}

	lines = strings.Split(out, "\n")

	if len(lines) != testLen+1 {
		t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
	}

	deleteContainer(cleanedContainerID)
	logDone("logs - logs tail")
}

func TestLogsFollowStopped(t *testing.T) {
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "echo", "hello")

	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	exec.Command(dockerBinary, "wait", cleanedContainerID).Run()

	logsCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID)
	if err := logsCmd.Start(); err != nil {
		t.Fatal(err)
	}

	c := make(chan struct{})
	go func() {
		if err := logsCmd.Wait(); err != nil {
			t.Fatal(err)
		}
		close(c)
	}()

	select {
	case <-c:
	case <-time.After(1 * time.Second):
		t.Fatal("Following logs is hanged")
	}

	deleteContainer(cleanedContainerID)
	logDone("logs - logs follow stopped container")
}

// Regression test for #8832
func TestLogsFollowSlowStdoutConsumer(t *testing.T) {
	runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "/bin/sh", "-c", `usleep 200000;yes X | head -c 200000`)

	out, _, _, err := runCommandWithStdoutStderr(runCmd)
	if err != nil {
		t.Fatalf("run failed with errors: %s, %v", out, err)
	}

	cleanedContainerID := stripTrailingCharacters(out)
	defer deleteContainer(cleanedContainerID)

	stopSlowRead := make(chan bool)

	go func() {
		exec.Command(dockerBinary, "wait", cleanedContainerID).Run()
		stopSlowRead <- true
	}()

	logCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID)

	stdout, err := logCmd.StdoutPipe()
	if err != nil {
		t.Fatal(err)
	}

	if err := logCmd.Start(); err != nil {
		t.Fatal(err)
	}

	// First read slowly
	bytes1, err := consumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead)
	if err != nil {
		t.Fatal(err)
	}

	// After the container has finished we can continue reading fast
	bytes2, err := consumeWithSpeed(stdout, 32*1024, 0, nil)
	if err != nil {
		t.Fatal(err)
	}

	actual := bytes1 + bytes2
	expected := 200000
	if actual != expected {
		t.Fatalf("Invalid bytes read: %d, expected %d", actual, expected)
	}

	logDone("logs - follow slow consumer")
}