github.com/damirazo/docker@v1.9.0/integration-cli/docker_cli_logs_test.go (about)

     1  package main
     2  
     3  import (
     4  	"encoding/json"
     5  	"fmt"
     6  	"io"
     7  	"os/exec"
     8  	"regexp"
     9  	"strconv"
    10  	"strings"
    11  	"time"
    12  
    13  	"github.com/docker/docker/pkg/timeutils"
    14  	"github.com/go-check/check"
    15  )
    16  
    17  // This used to work, it test a log of PageSize-1 (gh#4851)
    18  func (s *DockerSuite) TestLogsContainerSmallerThanPage(c *check.C) {
    19  	testRequires(c, DaemonIsLinux)
    20  	testLen := 32767
    21  	out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen))
    22  	cleanedContainerID := strings.TrimSpace(out)
    23  
    24  	dockerCmd(c, "wait", cleanedContainerID)
    25  	out, _ = dockerCmd(c, "logs", cleanedContainerID)
    26  	if len(out) != testLen+1 {
    27  		c.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out))
    28  	}
    29  }
    30  
    31  // Regression test: When going over the PageSize, it used to panic (gh#4851)
    32  func (s *DockerSuite) TestLogsContainerBiggerThanPage(c *check.C) {
    33  	testRequires(c, DaemonIsLinux)
    34  	testLen := 32768
    35  	out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen))
    36  
    37  	cleanedContainerID := strings.TrimSpace(out)
    38  	dockerCmd(c, "wait", cleanedContainerID)
    39  
    40  	out, _ = dockerCmd(c, "logs", cleanedContainerID)
    41  
    42  	if len(out) != testLen+1 {
    43  		c.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out))
    44  	}
    45  }
    46  
    47  // Regression test: When going much over the PageSize, it used to block (gh#4851)
    48  func (s *DockerSuite) TestLogsContainerMuchBiggerThanPage(c *check.C) {
    49  	testRequires(c, DaemonIsLinux)
    50  	testLen := 33000
    51  	out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen))
    52  
    53  	cleanedContainerID := strings.TrimSpace(out)
    54  	dockerCmd(c, "wait", cleanedContainerID)
    55  
    56  	out, _ = dockerCmd(c, "logs", cleanedContainerID)
    57  
    58  	if len(out) != testLen+1 {
    59  		c.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out))
    60  	}
    61  }
    62  
    63  func (s *DockerSuite) TestLogsTimestamps(c *check.C) {
    64  	testRequires(c, DaemonIsLinux)
    65  	testLen := 100
    66  	out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen))
    67  
    68  	cleanedContainerID := strings.TrimSpace(out)
    69  	dockerCmd(c, "wait", cleanedContainerID)
    70  
    71  	out, _ = dockerCmd(c, "logs", "-t", cleanedContainerID)
    72  
    73  	lines := strings.Split(out, "\n")
    74  
    75  	if len(lines) != testLen+1 {
    76  		c.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
    77  	}
    78  
    79  	ts := regexp.MustCompile(`^.* `)
    80  
    81  	for _, l := range lines {
    82  		if l != "" {
    83  			_, err := time.Parse(timeutils.RFC3339NanoFixed+" ", ts.FindString(l))
    84  			if err != nil {
    85  				c.Fatalf("Failed to parse timestamp from %v: %v", l, err)
    86  			}
    87  			if l[29] != 'Z' { // ensure we have padded 0's
    88  				c.Fatalf("Timestamp isn't padded properly: %s", l)
    89  			}
    90  		}
    91  	}
    92  }
    93  
    94  func (s *DockerSuite) TestLogsSeparateStderr(c *check.C) {
    95  	testRequires(c, DaemonIsLinux)
    96  	msg := "stderr_log"
    97  	out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg))
    98  
    99  	cleanedContainerID := strings.TrimSpace(out)
   100  	dockerCmd(c, "wait", cleanedContainerID)
   101  
   102  	stdout, stderr, _ := dockerCmdWithStdoutStderr(c, "logs", cleanedContainerID)
   103  
   104  	if stdout != "" {
   105  		c.Fatalf("Expected empty stdout stream, got %v", stdout)
   106  	}
   107  
   108  	stderr = strings.TrimSpace(stderr)
   109  	if stderr != msg {
   110  		c.Fatalf("Expected %v in stderr stream, got %v", msg, stderr)
   111  	}
   112  }
   113  
   114  func (s *DockerSuite) TestLogsStderrInStdout(c *check.C) {
   115  	testRequires(c, DaemonIsLinux)
   116  	msg := "stderr_log"
   117  	out, _ := dockerCmd(c, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg))
   118  
   119  	cleanedContainerID := strings.TrimSpace(out)
   120  	dockerCmd(c, "wait", cleanedContainerID)
   121  
   122  	stdout, stderr, _ := dockerCmdWithStdoutStderr(c, "logs", cleanedContainerID)
   123  	if stderr != "" {
   124  		c.Fatalf("Expected empty stderr stream, got %v", stderr)
   125  	}
   126  
   127  	stdout = strings.TrimSpace(stdout)
   128  	if stdout != msg {
   129  		c.Fatalf("Expected %v in stdout stream, got %v", msg, stdout)
   130  	}
   131  }
   132  
   133  func (s *DockerSuite) TestLogsTail(c *check.C) {
   134  	testRequires(c, DaemonIsLinux)
   135  	testLen := 100
   136  	out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen))
   137  
   138  	cleanedContainerID := strings.TrimSpace(out)
   139  	dockerCmd(c, "wait", cleanedContainerID)
   140  
   141  	out, _ = dockerCmd(c, "logs", "--tail", "5", cleanedContainerID)
   142  
   143  	lines := strings.Split(out, "\n")
   144  
   145  	if len(lines) != 6 {
   146  		c.Fatalf("Expected log %d lines, received %d\n", 6, len(lines))
   147  	}
   148  	out, _ = dockerCmd(c, "logs", "--tail", "all", cleanedContainerID)
   149  
   150  	lines = strings.Split(out, "\n")
   151  
   152  	if len(lines) != testLen+1 {
   153  		c.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
   154  	}
   155  	out, _, _ = dockerCmdWithStdoutStderr(c, "logs", "--tail", "random", cleanedContainerID)
   156  
   157  	lines = strings.Split(out, "\n")
   158  
   159  	if len(lines) != testLen+1 {
   160  		c.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
   161  	}
   162  }
   163  
   164  func (s *DockerSuite) TestLogsFollowStopped(c *check.C) {
   165  	testRequires(c, DaemonIsLinux)
   166  	out, _ := dockerCmd(c, "run", "-d", "busybox", "echo", "hello")
   167  
   168  	cleanedContainerID := strings.TrimSpace(out)
   169  	dockerCmd(c, "wait", cleanedContainerID)
   170  
   171  	logsCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID)
   172  	if err := logsCmd.Start(); err != nil {
   173  		c.Fatal(err)
   174  	}
   175  
   176  	errChan := make(chan error)
   177  	go func() {
   178  		errChan <- logsCmd.Wait()
   179  		close(errChan)
   180  	}()
   181  
   182  	select {
   183  	case err := <-errChan:
   184  		c.Assert(err, check.IsNil)
   185  	case <-time.After(1 * time.Second):
   186  		c.Fatal("Following logs is hanged")
   187  	}
   188  }
   189  
   190  func (s *DockerSuite) TestLogsSince(c *check.C) {
   191  	testRequires(c, DaemonIsLinux)
   192  	name := "testlogssince"
   193  	out, _ := dockerCmd(c, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo `date +%s` log$i; done")
   194  
   195  	log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
   196  	t, err := strconv.ParseInt(log2Line[0], 10, 64) // the timestamp log2 is written
   197  	c.Assert(err, check.IsNil)
   198  	since := t + 1 // add 1s so log1 & log2 doesn't show up
   199  	out, _ = dockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name)
   200  
   201  	// Skip 2 seconds
   202  	unexpected := []string{"log1", "log2"}
   203  	for _, v := range unexpected {
   204  		if strings.Contains(out, v) {
   205  			c.Fatalf("unexpected log message returned=%v, since=%v\nout=%v", v, since, out)
   206  		}
   207  	}
   208  	// Test with default value specified and parameter omitted
   209  	expected := []string{"log1", "log2", "log3"}
   210  	for _, cmd := range []*exec.Cmd{
   211  		exec.Command(dockerBinary, "logs", "-t", name),
   212  		exec.Command(dockerBinary, "logs", "-t", "--since=0", name),
   213  	} {
   214  		out, _, err = runCommandWithOutput(cmd)
   215  		if err != nil {
   216  			c.Fatalf("failed to log container: %s, %v", out, err)
   217  		}
   218  		for _, v := range expected {
   219  			if !strings.Contains(out, v) {
   220  				c.Fatalf("'%v' does not contain=%v\nout=%s", cmd.Args, v, out)
   221  			}
   222  		}
   223  	}
   224  }
   225  
   226  func (s *DockerSuite) TestLogsSinceFutureFollow(c *check.C) {
   227  	testRequires(c, DaemonIsLinux)
   228  	out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", `for i in $(seq 1 5); do date +%s; sleep 1; done`)
   229  	cleanedContainerID := strings.TrimSpace(out)
   230  
   231  	now := daemonTime(c).Unix()
   232  	since := now + 2
   233  	out, _ = dockerCmd(c, "logs", "-f", fmt.Sprintf("--since=%v", since), cleanedContainerID)
   234  	lines := strings.Split(strings.TrimSpace(out), "\n")
   235  	if len(lines) == 0 {
   236  		c.Fatal("got no log lines")
   237  	}
   238  	for _, v := range lines {
   239  		ts, err := strconv.ParseInt(v, 10, 64)
   240  		if err != nil {
   241  			c.Fatalf("cannot parse timestamp output from log: '%v'\nout=%s", v, out)
   242  		}
   243  		if ts < since {
   244  			c.Fatalf("earlier log found. since=%v logdate=%v", since, ts)
   245  		}
   246  	}
   247  }
   248  
   249  // Regression test for #8832
   250  func (s *DockerSuite) TestLogsFollowSlowStdoutConsumer(c *check.C) {
   251  	testRequires(c, DaemonIsLinux)
   252  	out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", `usleep 200000;yes X | head -c 200000`)
   253  
   254  	cleanedContainerID := strings.TrimSpace(out)
   255  
   256  	stopSlowRead := make(chan bool)
   257  
   258  	go func() {
   259  		exec.Command(dockerBinary, "wait", cleanedContainerID).Run()
   260  		stopSlowRead <- true
   261  	}()
   262  
   263  	logCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID)
   264  	stdout, err := logCmd.StdoutPipe()
   265  	c.Assert(err, check.IsNil)
   266  	c.Assert(logCmd.Start(), check.IsNil)
   267  
   268  	// First read slowly
   269  	bytes1, err := consumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead)
   270  	c.Assert(err, check.IsNil)
   271  
   272  	// After the container has finished we can continue reading fast
   273  	bytes2, err := consumeWithSpeed(stdout, 32*1024, 0, nil)
   274  	c.Assert(err, check.IsNil)
   275  
   276  	actual := bytes1 + bytes2
   277  	expected := 200000
   278  	if actual != expected {
   279  		c.Fatalf("Invalid bytes read: %d, expected %d", actual, expected)
   280  	}
   281  
   282  }
   283  
   284  func (s *DockerSuite) TestLogsFollowGoroutinesWithStdout(c *check.C) {
   285  	testRequires(c, DaemonIsLinux)
   286  	out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do echo hello; sleep 2; done")
   287  	id := strings.TrimSpace(out)
   288  	c.Assert(waitRun(id), check.IsNil)
   289  
   290  	type info struct {
   291  		NGoroutines int
   292  	}
   293  	getNGoroutines := func() int {
   294  		var i info
   295  		status, b, err := sockRequest("GET", "/info", nil)
   296  		c.Assert(err, check.IsNil)
   297  		c.Assert(status, check.Equals, 200)
   298  		c.Assert(json.Unmarshal(b, &i), check.IsNil)
   299  		return i.NGoroutines
   300  	}
   301  
   302  	nroutines := getNGoroutines()
   303  
   304  	cmd := exec.Command(dockerBinary, "logs", "-f", id)
   305  	r, w := io.Pipe()
   306  	cmd.Stdout = w
   307  	c.Assert(cmd.Start(), check.IsNil)
   308  
   309  	// Make sure pipe is written to
   310  	chErr := make(chan error)
   311  	go func() {
   312  		b := make([]byte, 1)
   313  		_, err := r.Read(b)
   314  		chErr <- err
   315  	}()
   316  	c.Assert(<-chErr, check.IsNil)
   317  	c.Assert(cmd.Process.Kill(), check.IsNil)
   318  
   319  	// NGoroutines is not updated right away, so we need to wait before failing
   320  	t := time.After(30 * time.Second)
   321  	for {
   322  		select {
   323  		case <-t:
   324  			if n := getNGoroutines(); n > nroutines {
   325  				c.Fatalf("leaked goroutines: expected less than or equal to %d, got: %d", nroutines, n)
   326  			}
   327  		default:
   328  			if n := getNGoroutines(); n <= nroutines {
   329  				return
   330  			}
   331  			time.Sleep(200 * time.Millisecond)
   332  		}
   333  	}
   334  }
   335  
   336  func (s *DockerSuite) TestLogsFollowGoroutinesNoOutput(c *check.C) {
   337  	testRequires(c, DaemonIsLinux)
   338  	out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do sleep 2; done")
   339  	id := strings.TrimSpace(out)
   340  	c.Assert(waitRun(id), check.IsNil)
   341  
   342  	type info struct {
   343  		NGoroutines int
   344  	}
   345  	getNGoroutines := func() int {
   346  		var i info
   347  		status, b, err := sockRequest("GET", "/info", nil)
   348  		c.Assert(err, check.IsNil)
   349  		c.Assert(status, check.Equals, 200)
   350  		c.Assert(json.Unmarshal(b, &i), check.IsNil)
   351  		return i.NGoroutines
   352  	}
   353  
   354  	nroutines := getNGoroutines()
   355  
   356  	cmd := exec.Command(dockerBinary, "logs", "-f", id)
   357  	c.Assert(cmd.Start(), check.IsNil)
   358  	time.Sleep(200 * time.Millisecond)
   359  	c.Assert(cmd.Process.Kill(), check.IsNil)
   360  
   361  	// NGoroutines is not updated right away, so we need to wait before failing
   362  	t := time.After(30 * time.Second)
   363  	for {
   364  		select {
   365  		case <-t:
   366  			if n := getNGoroutines(); n > nroutines {
   367  				c.Fatalf("leaked goroutines: expected less than or equal to %d, got: %d", nroutines, n)
   368  			}
   369  		default:
   370  			if n := getNGoroutines(); n <= nroutines {
   371  				return
   372  			}
   373  			time.Sleep(200 * time.Millisecond)
   374  		}
   375  	}
   376  }
   377  
   378  func (s *DockerSuite) TestLogsCLIContainerNotFound(c *check.C) {
   379  	name := "testlogsnocontainer"
   380  	out, _, _ := dockerCmdWithError("logs", name)
   381  	message := fmt.Sprintf(".*no such id: %s.*\n", name)
   382  	c.Assert(out, check.Matches, message)
   383  }