docker_cli_logs_test.go 11 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348
  1. package main
  2. import (
  3. "fmt"
  4. "io"
  5. "os/exec"
  6. "regexp"
  7. "strings"
  8. "testing"
  9. "time"
  10. "github.com/docker/docker/integration-cli/cli"
  11. "github.com/docker/docker/pkg/jsonmessage"
  12. "gotest.tools/v3/assert"
  13. "gotest.tools/v3/icmd"
  14. )
  15. type DockerCLILogsSuite struct {
  16. ds *DockerSuite
  17. }
  18. func (s *DockerCLILogsSuite) TearDownTest(c *testing.T) {
  19. s.ds.TearDownTest(c)
  20. }
  21. func (s *DockerCLILogsSuite) OnTimeout(c *testing.T) {
  22. s.ds.OnTimeout(c)
  23. }
  24. // This used to work, it test a log of PageSize-1 (gh#4851)
  25. func (s *DockerCLILogsSuite) TestLogsContainerSmallerThanPage(c *testing.T) {
  26. testLogsContainerPagination(c, 32767)
  27. }
  28. // Regression test: When going over the PageSize, it used to panic (gh#4851)
  29. func (s *DockerCLILogsSuite) TestLogsContainerBiggerThanPage(c *testing.T) {
  30. testLogsContainerPagination(c, 32768)
  31. }
  32. // Regression test: When going much over the PageSize, it used to block (gh#4851)
  33. func (s *DockerCLILogsSuite) TestLogsContainerMuchBiggerThanPage(c *testing.T) {
  34. testLogsContainerPagination(c, 33000)
  35. }
  36. func testLogsContainerPagination(c *testing.T, testLen int) {
  37. out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n = >> a.a; done; echo >> a.a; cat a.a", testLen))
  38. id := strings.TrimSpace(out)
  39. dockerCmd(c, "wait", id)
  40. out, _ = dockerCmd(c, "logs", id)
  41. assert.Equal(c, len(out), testLen+1)
  42. }
  43. func (s *DockerCLILogsSuite) TestLogsTimestamps(c *testing.T) {
  44. testLen := 100
  45. out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo = >> a.a; done; cat a.a", testLen))
  46. id := strings.TrimSpace(out)
  47. dockerCmd(c, "wait", id)
  48. out, _ = dockerCmd(c, "logs", "-t", id)
  49. lines := strings.Split(out, "\n")
  50. assert.Equal(c, len(lines), testLen+1)
  51. ts := regexp.MustCompile(`^.* `)
  52. for _, l := range lines {
  53. if l != "" {
  54. _, err := time.Parse(jsonmessage.RFC3339NanoFixed+" ", ts.FindString(l))
  55. assert.NilError(c, err, "Failed to parse timestamp from %v", l)
  56. // ensure we have padded 0's
  57. assert.Equal(c, l[29], uint8('Z'))
  58. }
  59. }
  60. }
  61. func (s *DockerCLILogsSuite) TestLogsSeparateStderr(c *testing.T) {
  62. msg := "stderr_log"
  63. out := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)).Combined()
  64. id := strings.TrimSpace(out)
  65. cli.DockerCmd(c, "wait", id)
  66. cli.DockerCmd(c, "logs", id).Assert(c, icmd.Expected{
  67. Out: "",
  68. Err: msg,
  69. })
  70. }
  71. func (s *DockerCLILogsSuite) TestLogsStderrInStdout(c *testing.T) {
  72. // TODO Windows: Needs investigation why this fails. Obtained string includes
  73. // a bunch of ANSI escape sequences before the "stderr_log" message.
  74. testRequires(c, DaemonIsLinux)
  75. msg := "stderr_log"
  76. out := cli.DockerCmd(c, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)).Combined()
  77. id := strings.TrimSpace(out)
  78. cli.DockerCmd(c, "wait", id)
  79. cli.DockerCmd(c, "logs", id).Assert(c, icmd.Expected{
  80. Out: msg,
  81. Err: "",
  82. })
  83. }
  84. func (s *DockerCLILogsSuite) TestLogsTail(c *testing.T) {
  85. testLen := 100
  86. out := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)).Combined()
  87. id := strings.TrimSpace(out)
  88. cli.DockerCmd(c, "wait", id)
  89. out = cli.DockerCmd(c, "logs", "--tail", "0", id).Combined()
  90. lines := strings.Split(out, "\n")
  91. assert.Equal(c, len(lines), 1)
  92. out = cli.DockerCmd(c, "logs", "--tail", "5", id).Combined()
  93. lines = strings.Split(out, "\n")
  94. assert.Equal(c, len(lines), 6)
  95. out = cli.DockerCmd(c, "logs", "--tail", "99", id).Combined()
  96. lines = strings.Split(out, "\n")
  97. assert.Equal(c, len(lines), 100)
  98. out = cli.DockerCmd(c, "logs", "--tail", "all", id).Combined()
  99. lines = strings.Split(out, "\n")
  100. assert.Equal(c, len(lines), testLen+1)
  101. out = cli.DockerCmd(c, "logs", "--tail", "-1", id).Combined()
  102. lines = strings.Split(out, "\n")
  103. assert.Equal(c, len(lines), testLen+1)
  104. out = cli.DockerCmd(c, "logs", "--tail", "random", id).Combined()
  105. lines = strings.Split(out, "\n")
  106. assert.Equal(c, len(lines), testLen+1)
  107. }
  108. func (s *DockerCLILogsSuite) TestLogsFollowStopped(c *testing.T) {
  109. dockerCmd(c, "run", "--name=test", "busybox", "echo", "hello")
  110. id := getIDByName(c, "test")
  111. logsCmd := exec.Command(dockerBinary, "logs", "-f", id)
  112. assert.NilError(c, logsCmd.Start())
  113. errChan := make(chan error, 1)
  114. go func() {
  115. errChan <- logsCmd.Wait()
  116. close(errChan)
  117. }()
  118. select {
  119. case err := <-errChan:
  120. assert.NilError(c, err)
  121. case <-time.After(30 * time.Second):
  122. c.Fatal("Following logs is hanged")
  123. }
  124. }
  125. func (s *DockerCLILogsSuite) TestLogsSince(c *testing.T) {
  126. name := "testlogssince"
  127. dockerCmd(c, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo log$i; done")
  128. out, _ := dockerCmd(c, "logs", "-t", name)
  129. log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
  130. t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // the timestamp log2 is written
  131. assert.NilError(c, err)
  132. since := t.Unix() + 1 // add 1s so log1 & log2 doesn't show up
  133. out, _ = dockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name)
  134. // Skip 2 seconds
  135. unexpected := []string{"log1", "log2"}
  136. for _, v := range unexpected {
  137. assert.Check(c, !strings.Contains(out, v), "unexpected log message returned, since=%v", since)
  138. }
  139. // Test to make sure a bad since format is caught by the client
  140. out, _, _ = dockerCmdWithError("logs", "-t", "--since=2006-01-02T15:04:0Z", name)
  141. assert.Assert(c, strings.Contains(out, `cannot parse "0Z" as "05"`), "bad since format passed to server")
  142. // Test with default value specified and parameter omitted
  143. expected := []string{"log1", "log2", "log3"}
  144. for _, cmd := range [][]string{
  145. {"logs", "-t", name},
  146. {"logs", "-t", "--since=0", name},
  147. } {
  148. result := icmd.RunCommand(dockerBinary, cmd...)
  149. result.Assert(c, icmd.Success)
  150. for _, v := range expected {
  151. assert.Check(c, strings.Contains(result.Combined(), v))
  152. }
  153. }
  154. }
  155. func (s *DockerCLILogsSuite) TestLogsSinceFutureFollow(c *testing.T) {
  156. // TODO Windows TP5 - Figure out why this test is so flakey. Disabled for now.
  157. testRequires(c, DaemonIsLinux)
  158. name := "testlogssincefuturefollow"
  159. dockerCmd(c, "run", "-d", "--name", name, "busybox", "/bin/sh", "-c", `for i in $(seq 1 5); do echo log$i; sleep 1; done`)
  160. // Extract one timestamp from the log file to give us a starting point for
  161. // our `--since` argument. Because the log producer runs in the background,
  162. // we need to check repeatedly for some output to be produced.
  163. var timestamp string
  164. for i := 0; i != 100 && timestamp == ""; i++ {
  165. if out, _ := dockerCmd(c, "logs", "-t", name); out == "" {
  166. time.Sleep(time.Millisecond * 100) // Retry
  167. } else {
  168. timestamp = strings.Split(strings.Split(out, "\n")[0], " ")[0]
  169. }
  170. }
  171. assert.Assert(c, timestamp != "")
  172. t, err := time.Parse(time.RFC3339Nano, timestamp)
  173. assert.NilError(c, err)
  174. since := t.Unix() + 2
  175. out, _ := dockerCmd(c, "logs", "-t", "-f", fmt.Sprintf("--since=%v", since), name)
  176. assert.Assert(c, len(out) != 0, "cannot read from empty log")
  177. lines := strings.Split(strings.TrimSpace(out), "\n")
  178. for _, v := range lines {
  179. ts, err := time.Parse(time.RFC3339Nano, strings.Split(v, " ")[0])
  180. assert.NilError(c, err, "cannot parse timestamp output from log: '%v'", v)
  181. assert.Assert(c, ts.Unix() >= since, "earlier log found. since=%v logdate=%v", since, ts)
  182. }
  183. }
  184. // Regression test for #8832
  185. func (s *DockerCLILogsSuite) TestLogsFollowSlowStdoutConsumer(c *testing.T) {
  186. // TODO Windows: Fix this test for TP5.
  187. testRequires(c, DaemonIsLinux)
  188. expected := 150000
  189. out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", fmt.Sprintf("usleep 600000; yes X | head -c %d", expected))
  190. id := strings.TrimSpace(out)
  191. stopSlowRead := make(chan bool)
  192. go func() {
  193. dockerCmd(c, "wait", id)
  194. stopSlowRead <- true
  195. }()
  196. logCmd := exec.Command(dockerBinary, "logs", "-f", id)
  197. stdout, err := logCmd.StdoutPipe()
  198. assert.NilError(c, err)
  199. assert.NilError(c, logCmd.Start())
  200. defer func() { go logCmd.Wait() }()
  201. // First read slowly
  202. bytes1, err := ConsumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead)
  203. assert.NilError(c, err)
  204. // After the container has finished we can continue reading fast
  205. bytes2, err := ConsumeWithSpeed(stdout, 32*1024, 0, nil)
  206. assert.NilError(c, err)
  207. assert.NilError(c, logCmd.Wait())
  208. actual := bytes1 + bytes2
  209. assert.Equal(c, actual, expected)
  210. }
  211. // ConsumeWithSpeed reads chunkSize bytes from reader before sleeping
  212. // for interval duration. Returns total read bytes. Send true to the
  213. // stop channel to return before reading to EOF on the reader.
  214. func ConsumeWithSpeed(reader io.Reader, chunkSize int, interval time.Duration, stop chan bool) (n int, err error) {
  215. buffer := make([]byte, chunkSize)
  216. for {
  217. var readBytes int
  218. readBytes, err = reader.Read(buffer)
  219. n += readBytes
  220. if err != nil {
  221. if err == io.EOF {
  222. err = nil
  223. }
  224. return
  225. }
  226. select {
  227. case <-stop:
  228. return
  229. case <-time.After(interval):
  230. }
  231. }
  232. }
  233. func (s *DockerCLILogsSuite) TestLogsFollowGoroutinesWithStdout(c *testing.T) {
  234. out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do echo hello; sleep 2; done")
  235. id := strings.TrimSpace(out)
  236. assert.NilError(c, waitRun(id))
  237. nroutines, err := getGoroutineNumber()
  238. assert.NilError(c, err)
  239. cmd := exec.Command(dockerBinary, "logs", "-f", id)
  240. r, w := io.Pipe()
  241. cmd.Stdout = w
  242. assert.NilError(c, cmd.Start())
  243. go cmd.Wait()
  244. // Make sure pipe is written to
  245. chErr := make(chan error)
  246. go func() {
  247. b := make([]byte, 1)
  248. _, err := r.Read(b)
  249. chErr <- err
  250. }()
  251. assert.NilError(c, <-chErr)
  252. assert.NilError(c, cmd.Process.Kill())
  253. r.Close()
  254. cmd.Wait()
  255. // NGoroutines is not updated right away, so we need to wait before failing
  256. assert.NilError(c, waitForGoroutines(nroutines))
  257. }
  258. func (s *DockerCLILogsSuite) TestLogsFollowGoroutinesNoOutput(c *testing.T) {
  259. out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do sleep 2; done")
  260. id := strings.TrimSpace(out)
  261. assert.NilError(c, waitRun(id))
  262. nroutines, err := getGoroutineNumber()
  263. assert.NilError(c, err)
  264. cmd := exec.Command(dockerBinary, "logs", "-f", id)
  265. assert.NilError(c, cmd.Start())
  266. go cmd.Wait()
  267. time.Sleep(200 * time.Millisecond)
  268. assert.NilError(c, cmd.Process.Kill())
  269. cmd.Wait()
  270. // NGoroutines is not updated right away, so we need to wait before failing
  271. assert.NilError(c, waitForGoroutines(nroutines))
  272. }
  273. func (s *DockerCLILogsSuite) TestLogsCLIContainerNotFound(c *testing.T) {
  274. name := "testlogsnocontainer"
  275. out, _, _ := dockerCmdWithError("logs", name)
  276. message := fmt.Sprintf("No such container: %s\n", name)
  277. assert.Assert(c, strings.Contains(out, message))
  278. }
  279. func (s *DockerCLILogsSuite) TestLogsWithDetails(c *testing.T) {
  280. dockerCmd(c, "run", "--name=test", "--label", "foo=bar", "-e", "baz=qux", "--log-opt", "labels=foo", "--log-opt", "env=baz", "busybox", "echo", "hello")
  281. out, _ := dockerCmd(c, "logs", "--details", "--timestamps", "test")
  282. logFields := strings.Fields(strings.TrimSpace(out))
  283. assert.Equal(c, len(logFields), 3, out)
  284. details := strings.Split(logFields[1], ",")
  285. assert.Equal(c, len(details), 2)
  286. assert.Equal(c, details[0], "baz=qux")
  287. assert.Equal(c, details[1], "foo=bar")
  288. }