From 7ab0f9bf6142b828ac8972fae6cb8aabcaf1d742 Mon Sep 17 00:00:00 2001 From: Aaron Lehmann Date: Mon, 7 Dec 2015 13:26:30 -0800 Subject: [PATCH] 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 --- integration-cli/docker_cli_logs_test.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/integration-cli/docker_cli_logs_test.go b/integration-cli/docker_cli_logs_test.go index 41780f8a41..b572475c73 100644 --- a/integration-cli/docker_cli_logs_test.go +++ b/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) { testRequires(c, DaemonIsLinux) 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], " ") - 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) - 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) // Skip 2 seconds