Browse Source

Fix flaky test TestLogsSince

This test can fail if it is run close to a second boundary:

    FAIL: docker_cli_logs_test.go:169: DockerSuite.TestLogsSince

    docker_cli_logs_test.go:183:
        c.Assert(out, checker.Not(checker.Contains), v,
    check.Commentf("unexpected log message returned, since=%v", since))
    ... obtained string = "" +
    ...     "2015-12-07T19:54:45.000551883Z 1449518084 log2\n" +
    ...     "2015-12-07T19:54:47.001310929Z 1449518086 log3\n"
    ... substring string = "log2"
    ... unexpected log message returned, since=1449518085

The problem is that it generates log lines using date +%s and uses that
timestamp as a reference for log filtering with (--since) later on in
the test. However, the timestamp that date +%s generates may not match
the log timestamp.

This commit changes the test to parse the log timestamp itself instead
of relying on a parallel timestamp.

Signed-off-by: Aaron Lehmann <aaron.lehmann@docker.com>
Aaron Lehmann 9 years ago
parent
commit
7ab0f9bf61
1 changed files with 4 additions and 3 deletions
  1. 4 3
      integration-cli/docker_cli_logs_test.go

+ 4 - 3
integration-cli/docker_cli_logs_test.go

@@ -169,12 +169,13 @@ func (s *DockerSuite) TestLogsFollowStopped(c *check.C) {
 func (s *DockerSuite) TestLogsSince(c *check.C) {
 func (s *DockerSuite) TestLogsSince(c *check.C) {
 	testRequires(c, DaemonIsLinux)
 	testRequires(c, DaemonIsLinux)
 	name := "testlogssince"
 	name := "testlogssince"
-	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")
+	dockerCmd(c, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo log$i; done")
+	out, _ := dockerCmd(c, "logs", "-t", name)
 
 
 	log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
 	log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
-	t, err := strconv.ParseInt(log2Line[0], 10, 64) // the timestamp log2 is written
+	t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // the timestamp log2 is written
 	c.Assert(err, checker.IsNil)
 	c.Assert(err, checker.IsNil)
-	since := t + 1 // add 1s so log1 & log2 doesn't show up
+	since := t.Unix() + 1 // add 1s so log1 & log2 doesn't show up
 	out, _ = dockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name)
 	out, _ = dockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name)
 
 
 	// Skip 2 seconds
 	// Skip 2 seconds