docker_cli_service_logs_test.go 14 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388
  1. // +build !windows
  2. package main
  3. import (
  4. "bufio"
  5. "fmt"
  6. "io"
  7. "os/exec"
  8. "strings"
  9. "time"
  10. "github.com/docker/docker/integration-cli/checker"
  11. "github.com/docker/docker/integration-cli/daemon"
  12. "github.com/go-check/check"
  13. "github.com/gotestyourself/gotestyourself/icmd"
  14. )
  15. type logMessage struct {
  16. err error
  17. data []byte
  18. }
  19. func (s *DockerSwarmSuite) TestServiceLogs(c *check.C) {
  20. d := s.AddDaemon(c, true, true)
  21. // we have multiple services here for detecting the goroutine issue #28915
  22. services := map[string]string{
  23. "TestServiceLogs1": "hello1",
  24. "TestServiceLogs2": "hello2",
  25. }
  26. for name, message := range services {
  27. out, err := d.Cmd("service", "create", "--detach", "--no-resolve-image", "--name", name, "busybox",
  28. "sh", "-c", fmt.Sprintf("echo %s; tail -f /dev/null", message))
  29. c.Assert(err, checker.IsNil)
  30. c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  31. }
  32. // make sure task has been deployed.
  33. waitAndAssert(c, defaultReconciliationTimeout,
  34. d.CheckRunningTaskImages, checker.DeepEquals,
  35. map[string]int{"busybox:latest": len(services)})
  36. for name, message := range services {
  37. out, err := d.Cmd("service", "logs", name)
  38. c.Assert(err, checker.IsNil)
  39. c.Logf("log for %q: %q", name, out)
  40. c.Assert(out, checker.Contains, message)
  41. }
  42. }
  43. // countLogLines returns a closure that can be used with waitAndAssert to
  44. // verify that a minimum number of expected container log messages have been
  45. // output.
  46. func countLogLines(d *daemon.Swarm, name string) func(*check.C) (interface{}, check.CommentInterface) {
  47. return func(c *check.C) (interface{}, check.CommentInterface) {
  48. result := icmd.RunCmd(d.Command("service", "logs", "-t", "--raw", name))
  49. result.Assert(c, icmd.Expected{})
  50. // if this returns an emptystring, trying to split it later will return
  51. // an array containing emptystring. a valid log line will NEVER be
  52. // emptystring because we ask for the timestamp.
  53. if result.Stdout() == "" {
  54. return 0, check.Commentf("Empty stdout")
  55. }
  56. lines := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
  57. return len(lines), check.Commentf("output, %q", string(result.Stdout()))
  58. }
  59. }
  60. func (s *DockerSwarmSuite) TestServiceLogsCompleteness(c *check.C) {
  61. d := s.AddDaemon(c, true, true)
  62. name := "TestServiceLogsCompleteness"
  63. // make a service that prints 6 lines
  64. out, err := d.Cmd("service", "create", "--detach", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "for line in $(seq 0 5); do echo log test $line; done; sleep 100000")
  65. c.Assert(err, checker.IsNil)
  66. c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  67. // make sure task has been deployed.
  68. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  69. // and make sure we have all the log lines
  70. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6)
  71. out, err = d.Cmd("service", "logs", name)
  72. c.Assert(err, checker.IsNil)
  73. lines := strings.Split(strings.TrimSpace(out), "\n")
  74. // i have heard anecdotal reports that logs may come back from the engine
  75. // mis-ordered. if this tests fails, consider the possibility that that
  76. // might be occurring
  77. for i, line := range lines {
  78. c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i))
  79. }
  80. }
  81. func (s *DockerSwarmSuite) TestServiceLogsTail(c *check.C) {
  82. d := s.AddDaemon(c, true, true)
  83. name := "TestServiceLogsTail"
  84. // make a service that prints 6 lines
  85. out, err := d.Cmd("service", "create", "--detach", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "for line in $(seq 1 6); do echo log test $line; done; sleep 100000")
  86. c.Assert(err, checker.IsNil)
  87. c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  88. // make sure task has been deployed.
  89. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  90. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6)
  91. out, err = d.Cmd("service", "logs", "--tail=2", name)
  92. c.Assert(err, checker.IsNil)
  93. lines := strings.Split(strings.TrimSpace(out), "\n")
  94. for i, line := range lines {
  95. // doing i+5 is hacky but not too fragile, it's good enough. if it flakes something else is wrong
  96. c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i+5))
  97. }
  98. }
  99. func (s *DockerSwarmSuite) TestServiceLogsSince(c *check.C) {
  100. // See DockerSuite.TestLogsSince, which is where this comes from
  101. d := s.AddDaemon(c, true, true)
  102. name := "TestServiceLogsSince"
  103. out, err := d.Cmd("service", "create", "--detach", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "for i in $(seq 1 3); do sleep .1; echo log$i; done; sleep 10000000")
  104. c.Assert(err, checker.IsNil)
  105. c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  106. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  107. // wait a sec for the logs to come in
  108. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 3)
  109. out, err = d.Cmd("service", "logs", "-t", name)
  110. c.Assert(err, checker.IsNil)
  111. log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
  112. t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // timestamp log2 is written
  113. c.Assert(err, checker.IsNil)
  114. u := t.Add(50 * time.Millisecond) // add .05s so log1 & log2 don't show up
  115. since := u.Format(time.RFC3339Nano)
  116. out, err = d.Cmd("service", "logs", "-t", fmt.Sprintf("--since=%v", since), name)
  117. c.Assert(err, checker.IsNil)
  118. unexpected := []string{"log1", "log2"}
  119. expected := []string{"log3"}
  120. for _, v := range unexpected {
  121. c.Assert(out, checker.Not(checker.Contains), v, check.Commentf("unexpected log message returned, since=%v", u))
  122. }
  123. for _, v := range expected {
  124. c.Assert(out, checker.Contains, v, check.Commentf("expected log message %v, was not present, since=%v", u))
  125. }
  126. }
  127. func (s *DockerSwarmSuite) TestServiceLogsFollow(c *check.C) {
  128. d := s.AddDaemon(c, true, true)
  129. name := "TestServiceLogsFollow"
  130. out, err := d.Cmd("service", "create", "--detach", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "while true; do echo log test; sleep 0.1; done")
  131. c.Assert(err, checker.IsNil)
  132. c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  133. // make sure task has been deployed.
  134. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  135. args := []string{"service", "logs", "-f", name}
  136. cmd := exec.Command(dockerBinary, d.PrependHostArg(args)...)
  137. r, w := io.Pipe()
  138. cmd.Stdout = w
  139. cmd.Stderr = w
  140. c.Assert(cmd.Start(), checker.IsNil)
  141. go cmd.Wait()
  142. // Make sure pipe is written to
  143. ch := make(chan *logMessage)
  144. done := make(chan struct{})
  145. go func() {
  146. reader := bufio.NewReader(r)
  147. for {
  148. msg := &logMessage{}
  149. msg.data, _, msg.err = reader.ReadLine()
  150. select {
  151. case ch <- msg:
  152. case <-done:
  153. return
  154. }
  155. }
  156. }()
  157. for i := 0; i < 3; i++ {
  158. msg := <-ch
  159. c.Assert(msg.err, checker.IsNil)
  160. c.Assert(string(msg.data), checker.Contains, "log test")
  161. }
  162. close(done)
  163. c.Assert(cmd.Process.Kill(), checker.IsNil)
  164. }
  165. func (s *DockerSwarmSuite) TestServiceLogsTaskLogs(c *check.C) {
  166. d := s.AddDaemon(c, true, true)
  167. name := "TestServicelogsTaskLogs"
  168. replicas := 2
  169. result := icmd.RunCmd(d.Command(
  170. // create a service with the name
  171. "service", "create", "--detach", "--no-resolve-image", "--name", name,
  172. // which has some number of replicas
  173. fmt.Sprintf("--replicas=%v", replicas),
  174. // which has this the task id as an environment variable templated in
  175. "--env", "TASK={{.Task.ID}}",
  176. // and runs this command to print exactly 6 logs lines
  177. "busybox", "sh", "-c", "for line in $(seq 0 5); do echo $TASK log test $line; done; sleep 100000",
  178. ))
  179. result.Assert(c, icmd.Expected{})
  180. // ^^ verify that we get no error
  181. // then verify that we have an id in stdout
  182. id := strings.TrimSpace(result.Stdout())
  183. c.Assert(id, checker.Not(checker.Equals), "")
  184. // so, right here, we're basically inspecting by id and returning only
  185. // the ID. if they don't match, the service doesn't exist.
  186. result = icmd.RunCmd(d.Command("service", "inspect", "--format=\"{{.ID}}\"", id))
  187. result.Assert(c, icmd.Expected{Out: id})
  188. // make sure task has been deployed.
  189. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, replicas)
  190. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6*replicas)
  191. // get the task ids
  192. result = icmd.RunCmd(d.Command("service", "ps", "-q", name))
  193. result.Assert(c, icmd.Expected{})
  194. // make sure we have two tasks
  195. taskIDs := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
  196. c.Assert(taskIDs, checker.HasLen, replicas)
  197. for _, taskID := range taskIDs {
  198. c.Logf("checking task %v", taskID)
  199. result := icmd.RunCmd(d.Command("service", "logs", taskID))
  200. result.Assert(c, icmd.Expected{})
  201. lines := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
  202. c.Logf("checking messages for %v", taskID)
  203. for i, line := range lines {
  204. // make sure the message is in order
  205. c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i))
  206. // make sure it contains the task id
  207. c.Assert(line, checker.Contains, taskID)
  208. }
  209. }
  210. }
  211. func (s *DockerSwarmSuite) TestServiceLogsTTY(c *check.C) {
  212. d := s.AddDaemon(c, true, true)
  213. name := "TestServiceLogsTTY"
  214. result := icmd.RunCmd(d.Command(
  215. // create a service
  216. "service", "create", "--detach", "--no-resolve-image",
  217. // name it $name
  218. "--name", name,
  219. // use a TTY
  220. "-t",
  221. // busybox image, shell string
  222. "busybox", "sh", "-c",
  223. // echo to stdout and stderr
  224. "echo out; (echo err 1>&2); sleep 10000",
  225. ))
  226. result.Assert(c, icmd.Expected{})
  227. id := strings.TrimSpace(result.Stdout())
  228. c.Assert(id, checker.Not(checker.Equals), "")
  229. // so, right here, we're basically inspecting by id and returning only
  230. // the ID. if they don't match, the service doesn't exist.
  231. result = icmd.RunCmd(d.Command("service", "inspect", "--format=\"{{.ID}}\"", id))
  232. result.Assert(c, icmd.Expected{Out: id})
  233. // make sure task has been deployed.
  234. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  235. // and make sure we have all the log lines
  236. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2)
  237. cmd := d.Command("service", "logs", "--raw", name)
  238. result = icmd.RunCmd(cmd)
  239. // for some reason there is carriage return in the output. i think this is
  240. // just expected.
  241. result.Assert(c, icmd.Expected{Out: "out\r\nerr\r\n"})
  242. }
  243. func (s *DockerSwarmSuite) TestServiceLogsNoHangDeletedContainer(c *check.C) {
  244. d := s.AddDaemon(c, true, true)
  245. name := "TestServiceLogsNoHangDeletedContainer"
  246. result := icmd.RunCmd(d.Command(
  247. // create a service
  248. "service", "create", "--detach", "--no-resolve-image",
  249. // name it $name
  250. "--name", name,
  251. // busybox image, shell string
  252. "busybox", "sh", "-c",
  253. // echo to stdout and stderr
  254. "while true; do echo line; sleep 2; done",
  255. ))
  256. // confirm that the command succeeded
  257. result.Assert(c, icmd.Expected{})
  258. // get the service id
  259. id := strings.TrimSpace(result.Stdout())
  260. c.Assert(id, checker.Not(checker.Equals), "")
  261. // make sure task has been deployed.
  262. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  263. // and make sure we have all the log lines
  264. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2)
  265. // now find and nuke the container
  266. result = icmd.RunCmd(d.Command("ps", "-q"))
  267. containerID := strings.TrimSpace(result.Stdout())
  268. c.Assert(containerID, checker.Not(checker.Equals), "")
  269. result = icmd.RunCmd(d.Command("stop", containerID))
  270. result.Assert(c, icmd.Expected{Out: containerID})
  271. result = icmd.RunCmd(d.Command("rm", containerID))
  272. result.Assert(c, icmd.Expected{Out: containerID})
  273. // run logs. use tail 2 to make sure we don't try to get a bunch of logs
  274. // somehow and slow down execution time
  275. cmd := d.Command("service", "logs", "--tail", "2", id)
  276. // start the command and then wait for it to finish with a 3 second timeout
  277. result = icmd.StartCmd(cmd)
  278. result = icmd.WaitOnCmd(3*time.Second, result)
  279. // then, assert that the result matches expected. if the command timed out,
  280. // if the command is timed out, result.Timeout will be true, but the
  281. // Expected defaults to false
  282. result.Assert(c, icmd.Expected{})
  283. }
  284. func (s *DockerSwarmSuite) TestServiceLogsDetails(c *check.C) {
  285. d := s.AddDaemon(c, true, true)
  286. name := "TestServiceLogsDetails"
  287. result := icmd.RunCmd(d.Command(
  288. // create a service
  289. "service", "create", "--detach", "--no-resolve-image",
  290. // name it $name
  291. "--name", name,
  292. // add an environment variable
  293. "--env", "asdf=test1",
  294. // add a log driver (without explicitly setting a driver, log-opt doesn't work)
  295. "--log-driver", "json-file",
  296. // add a log option to print the environment variable
  297. "--log-opt", "env=asdf",
  298. // busybox image, shell string
  299. "busybox", "sh", "-c",
  300. // make a log line
  301. "echo LogLine; while true; do sleep 1; done;",
  302. ))
  303. result.Assert(c, icmd.Expected{})
  304. id := strings.TrimSpace(result.Stdout())
  305. c.Assert(id, checker.Not(checker.Equals), "")
  306. // make sure task has been deployed
  307. waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  308. // and make sure we have all the log lines
  309. waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 1)
  310. // First, test without pretty printing
  311. // call service logs with details. set raw to skip pretty printing
  312. result = icmd.RunCmd(d.Command("service", "logs", "--raw", "--details", name))
  313. // in this case, we should get details and we should get log message, but
  314. // there will also be context as details (which will fall after the detail
  315. // we inserted in alphabetical order
  316. result.Assert(c, icmd.Expected{Out: "asdf=test1"})
  317. result.Assert(c, icmd.Expected{Out: "LogLine"})
  318. // call service logs with details. this time, don't pass raw
  319. result = icmd.RunCmd(d.Command("service", "logs", "--details", id))
  320. // in this case, we should get details space logmessage as well. the context
  321. // is part of the pretty part of the logline
  322. result.Assert(c, icmd.Expected{Out: "asdf=test1 LogLine"})
  323. }