From 851fe00c64ffafeb27b12f7b0ed8e41f7720b477 Mon Sep 17 00:00:00 2001 From: David Calavera Date: Mon, 28 Dec 2015 15:15:34 -0500 Subject: [PATCH] Add filter by event type and documentation. Signed-off-by: David Calavera --- api/client/events.go | 27 ++- api/client/stats.go | 23 ++- daemon/events/filter.go | 44 +++-- docs/misc/deprecated.md | 6 + docs/reference/api/docker_remote_api_v1.22.md | 64 ++++++- docs/reference/commandline/events.md | 105 ++++++----- integration-cli/docker_cli_build_test.go | 85 --------- integration-cli/docker_cli_build_unix_test.go | 90 +++++++++- integration-cli/docker_cli_events_test.go | 168 +++++++++--------- .../docker_cli_events_unix_test.go | 140 +++++++++++++++ integration-cli/events_utils.go | 80 +++++---- 11 files changed, 552 insertions(+), 280 deletions(-) diff --git a/api/client/events.go b/api/client/events.go index 14f0f6e9bd..4ceaf43f84 100644 --- a/api/client/events.go +++ b/api/client/events.go @@ -58,16 +58,29 @@ func (cli *DockerCli) CmdEvents(args ...string) error { // streamEvents decodes prints the incoming events in the provided output. func streamEvents(input io.Reader, output io.Writer) error { - dec := json.NewDecoder(input) - for { - var event eventtypes.Message - if err := dec.Decode(&event); err != nil { - if err == io.EOF { - break - } + return decodeEvents(input, func(event eventtypes.Message, err error) error { + if err != nil { return err } printOutput(event, output) + return nil + }) +} + +type eventProcessor func(event eventtypes.Message, err error) error + +func decodeEvents(input io.Reader, ep eventProcessor) error { + dec := json.NewDecoder(input) + for { + var event eventtypes.Message + err := dec.Decode(&event) + if err != nil && err == io.EOF { + break + } + + if procErr := ep(event, err); procErr != nil { + return procErr + } } return nil } diff --git a/api/client/stats.go b/api/client/stats.go index c5c9a8f7db..968d17eab4 100644 --- a/api/client/stats.go +++ b/api/client/stats.go @@ -11,8 +11,9 @@ import ( "time" "github.com/docker/docker/api/types" + "github.com/docker/docker/api/types/events" + "github.com/docker/docker/api/types/filters" Cli "github.com/docker/docker/cli" - "github.com/docker/docker/pkg/jsonmessage" "github.com/docker/go-units" ) @@ -189,7 +190,11 @@ func (cli *DockerCli) CmdStats(args ...string) error { err error } getNewContainers := func(c chan<- watch) { - options := types.EventsOptions{} + f := filters.NewArgs() + f.Add("type", "container") + options := types.EventsOptions{ + Filters: f, + } resBody, err := cli.client.Events(options) if err != nil { c <- watch{err: err} @@ -197,15 +202,15 @@ func (cli *DockerCli) CmdStats(args ...string) error { } defer resBody.Close() - dec := json.NewDecoder(resBody) - for { - var j *jsonmessage.JSONMessage - if err := dec.Decode(&j); err != nil { + decodeEvents(resBody, func(event events.Message, err error) error { + if err != nil { c <- watch{err: err} - return + return nil } - c <- watch{j.ID[:12], j.Status, nil} - } + + c <- watch{event.ID[:12], event.Action, nil} + return nil + }) } go func(stopChan chan<- error) { cChan := make(chan watch) diff --git a/daemon/events/filter.go b/daemon/events/filter.go index 0d690eed31..fc4fa7aae1 100644 --- a/daemon/events/filter.go +++ b/daemon/events/filter.go @@ -18,16 +18,16 @@ func NewFilter(filter filters.Args) *Filter { // Include returns true when the event ev is included by the filters func (ef *Filter) Include(ev events.Message) bool { - if ev.Type != events.ContainerEventType && ev.Type != events.ImageEventType { - return false - } return ef.filter.ExactMatch("event", ev.Action) && + ef.filter.ExactMatch("type", ev.Type) && ef.matchContainer(ev) && - ef.isImageIncluded(ev) && - ef.isLabelFieldIncluded(ev.Actor.Attributes) + ef.matchVolume(ev) && + ef.matchNetwork(ev) && + ef.matchImage(ev) && + ef.matchLabels(ev.Actor.Attributes) } -func (ef *Filter) isLabelFieldIncluded(attributes map[string]string) bool { +func (ef *Filter) matchLabels(attributes map[string]string) bool { if !ef.filter.Include("label") { return true } @@ -35,18 +35,36 @@ func (ef *Filter) isLabelFieldIncluded(attributes map[string]string) bool { } func (ef *Filter) matchContainer(ev events.Message) bool { - return ef.filter.FuzzyMatch("container", ev.Actor.ID) || - ef.filter.FuzzyMatch("container", ev.Actor.Attributes["name"]) + return ef.fuzzyMatchName(ev, events.ContainerEventType) } -// The image filter will be matched against both event.ID (for image events) -// and event.From (for container events), so that any container that was created +func (ef *Filter) matchVolume(ev events.Message) bool { + return ef.fuzzyMatchName(ev, events.VolumeEventType) +} + +func (ef *Filter) matchNetwork(ev events.Message) bool { + return ef.fuzzyMatchName(ev, events.NetworkEventType) +} + +func (ef *Filter) fuzzyMatchName(ev events.Message, eventType string) bool { + return ef.filter.FuzzyMatch(eventType, ev.Actor.ID) || + ef.filter.FuzzyMatch(eventType, ev.Actor.Attributes["name"]) +} + +// matchImage matches against both event.Actor.ID (for image events) +// and event.Actor.Attributes["image"] (for container events), so that any container that was created // from an image will be included in the image events. Also compare both // against the stripped repo name without any tags. -func (ef *Filter) isImageIncluded(ev events.Message) bool { - id := ev.ID +func (ef *Filter) matchImage(ev events.Message) bool { + id := ev.Actor.ID + nameAttr := "image" var imageName string - if n, ok := ev.Actor.Attributes["image"]; ok { + + if ev.Type == events.ImageEventType { + nameAttr = "name" + } + + if n, ok := ev.Actor.Attributes[nameAttr]; ok { imageName = n } return ef.filter.ExactMatch("image", id) || diff --git a/docs/misc/deprecated.md b/docs/misc/deprecated.md index a5d62123ff..d455f1349e 100644 --- a/docs/misc/deprecated.md +++ b/docs/misc/deprecated.md @@ -12,6 +12,12 @@ parent = "mn_use_docker" The following list of features are deprecated. +### Ambiguous event fields in API +**Deprecated In Release: v1.10** + +The fields `ID`, `Status` and `From` in the events API have been deprecated in favor of a more rich structure. +See the events API documentation for the new format. + ### `-f` flag on `docker tag` **Deprecated In Release: v1.10** diff --git a/docs/reference/api/docker_remote_api_v1.22.md b/docs/reference/api/docker_remote_api_v1.22.md index c829d5f255..e8008e2781 100644 --- a/docs/reference/api/docker_remote_api_v1.22.md +++ b/docs/reference/api/docker_remote_api_v1.22.md @@ -2263,17 +2263,24 @@ Status Codes: `GET /events` -Get container events from docker, either in real time via streaming, or via -polling (using since). +Get container events from docker, either in real time via streaming, or via polling (using since). Docker containers report the following events: - attach, commit, copy, create, destroy, die, exec_create, exec_start, export, kill, oom, pause, rename, resize, restart, start, stop, top, unpause + attach, commit, copy, create, destroy, die, exec_create, exec_start, export, kill, oom, pause, rename, resize, restart, start, stop, top, unpause, update -and Docker images report: +Docker images report the following events: delete, import, pull, push, tag, untag +Docker volumes report the following events: + + create, mount, unmount, destroy + +Docker networks report the following events: + + create, connect, disconnect, destroy + **Example request**: GET /events?since=1374067924 @@ -2283,10 +2290,48 @@ and Docker images report: HTTP/1.1 200 OK Content-Type: application/json - {"status":"pull","id":"busybox:latest","time":1442421700,"timeNano":1442421700598988358} - {"status":"create","id":"5745704abe9caa5","from":"busybox","time":1442421716,"timeNano":1442421716853979870} - {"status":"attach","id":"5745704abe9caa5","from":"busybox","time":1442421716,"timeNano":1442421716894759198} - {"status":"start","id":"5745704abe9caa5","from":"busybox","time":1442421716,"timeNano":1442421716983607193} + [ + { + "action": "pull", + "type": "image", + "actor": { + "id": "busybox:latest", + "attributes": {} + } + "time": 1442421700, + "timeNano": 1442421700598988358 + }, + { + "action": "create", + "type": "container", + "actor": { + "id": "5745704abe9caa5", + "attributes": {"image": "busybox"} + } + "time": 1442421716, + "timeNano": 1442421716853979870 + }, + { + "action": "attach", + "type": "container", + "actor": { + "id": "5745704abe9caa5", + "attributes": {"image": "busybox"} + } + "time": 1442421716, + "timeNano": 1442421716894759198 + }, + { + "action": "start", + "type": "container", + "actor": { + "id": "5745704abe9caa5", + "attributes": {"image": "busybox"} + } + "time": 1442421716, + "timeNano": 1442421716983607193 + } + ] Query Parameters: @@ -2297,6 +2342,9 @@ Query Parameters: - `event=`; -- event to filter - `image=`; -- image to filter - `label=`; -- image and container label to filter + - `type=`; -- either `container` or `image` or `volume` or `network` + - `volume=`; -- volume to filter + - `network=`; -- network to filter Status Codes: diff --git a/docs/reference/commandline/events.md b/docs/reference/commandline/events.md index 1af0e2337a..30eae105d9 100644 --- a/docs/reference/commandline/events.md +++ b/docs/reference/commandline/events.md @@ -19,14 +19,22 @@ parent = "smn_cli" --since="" Show all events created since timestamp --until="" Stream events until this timestamp -Docker containers will report the following events: +Docker containers report the following events: - attach, commit, copy, create, destroy, die, exec_create, exec_start, export, kill, oom, pause, rename, resize, restart, start, stop, top, unpause + attach, commit, copy, create, destroy, die, exec_create, exec_start, export, kill, oom, pause, rename, resize, restart, start, stop, top, unpause, update -and Docker images will report: +Docker images report the following events: delete, import, pull, push, tag, untag +Docker volumes report the following events: + + create, mount, unmount, destroy + +Docker networks report the following events: + + create, connect, disconnect, destroy + The `--since` and `--until` parameters can be Unix timestamps, date formatted timestamps, or Go duration strings (e.g. `10m`, `1h30m`) computed relative to the client machine’s time. If you do not provide the --since option, @@ -57,9 +65,12 @@ container container 588a23dac085 *AND* the event type is *start* The currently supported filters are: * container (`container=`) -* event (`event=`) +* event (`event=`) * image (`image=`) * label (`label=` or `label==`) +* type (`type=`) +* volume (`volume=`) +* network (`network=`) ## Examples @@ -77,68 +88,78 @@ You'll need two shells for this example. **Shell 1: (Again .. now showing events):** - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) start - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2015-05-12T11:51:30.999999999Z07:00 container start 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T11:51:30.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:52:12.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:53:45.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2015-05-12T15:54:03.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) **Show events in the past from a specified time:** $ docker events --since 1378216169 - 2014-03-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-03-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2015-05-12T11:51:30.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:52:12.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:53:45.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2015-05-12T15:54:03.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) $ docker events --since '2013-09-03' - 2014-09-03T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) start - 2014-09-03T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-09-03T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2015-05-12T11:51:30.999999999Z07:00 container start 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T11:51:30.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:52:12.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:53:45.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2015-05-12T15:54:03.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) $ docker events --since '2013-09-03T15:49:29' - 2014-09-03T15:49:29.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-09-03T15:49:29.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2015-05-12T11:51:30.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:52:12.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:53:45.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2015-05-12T15:54:03.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) This example outputs all events that were generated in the last 3 minutes, relative to the current time on the client machine: $ docker events --since '3m' - 2015-05-12T11:51:30.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2015-05-12T15:52:12.999999999Z07:00 4 4386fb97867d: (from ubuntu-1:14.04) stop - 2015-05-12T15:53:45.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2015-05-12T15:54:03.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2015-05-12T11:51:30.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:52:12.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2015-05-12T15:53:45.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2015-05-12T15:54:03.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) **Filter events:** $ docker events --filter 'event=stop' - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-09-03T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2014-05-10T17:42:14.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2014-09-03T17:42:14.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) $ docker events --filter 'image=ubuntu-1:14.04' - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) start - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop + 2014-05-10T17:42:14.999999999Z07:00 container start 4386fb97867d (image=ubuntu-1:14.04) + 2014-05-10T17:42:14.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2014-05-10T17:42:14.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) $ docker events --filter 'container=7805c1d35632' - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-09-03T15:49:29.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2014-05-10T17:42:14.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2014-09-03T15:49:29.999999999Z07:00 container stop 7805c1d35632 (image= redis:2.8) $ docker events --filter 'container=7805c1d35632' --filter 'container=4386fb97867d' - 2014-09-03T15:49:29.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-09-03T15:49:29.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2014-09-03T15:49:29.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2014-05-10T17:42:14.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2014-05-10T17:42:14.999999999Z07:00 container die 7805c1d35632 (image=redis:2.8) + 2014-09-03T15:49:29.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) $ docker events --filter 'container=7805c1d35632' --filter 'event=stop' - 2014-09-03T15:49:29.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2014-09-03T15:49:29.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) $ docker events --filter 'container=container_1' --filter 'container=container_2' - 2014-09-03T15:49:29.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) die - 2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from ubuntu-1:14.04) stop - 2014-05-10T17:42:14.999999999Z07:00 7805c1d35632: (from redis:2.8) die - 2014-09-03T15:49:29.999999999Z07:00 7805c1d35632: (from redis:2.8) stop + 2014-09-03T15:49:29.999999999Z07:00 container die 4386fb97867d (image=ubuntu-1:14.04) + 2014-05-10T17:42:14.999999999Z07:00 container stop 4386fb97867d (image=ubuntu-1:14.04) + 2014-05-10T17:42:14.999999999Z07:00 container die 7805c1d35632 (imager=redis:2.8) + 2014-09-03T15:49:29.999999999Z07:00 container stop 7805c1d35632 (image=redis:2.8) + + $ docker events --filter 'type=volume' + 2015-12-23T21:05:28.136212689Z volume create test-event-volume-local (driver=local) + 2015-12-23T21:05:28.383462717Z volume mount test-event-volume-local (read/write=true, container=562fe10671e9273da25eed36cdce26159085ac7ee6707105fd534866340a5025, destination=/foo, driver=local, propagation=rprivate) + 2015-12-23T21:05:28.650314265Z volume unmount test-event-volume-local (container=562fe10671e9273da25eed36cdce26159085ac7ee6707105fd534866340a5025, driver=local) + 2015-12-23T21:05:28.716218405Z volume destroy test-event-volume-local (driver=local) + + $ docker events --filter 'type=network' + 2015-12-23T21:38:24.705709133Z network create 8b111217944ba0ba844a65b13efcd57dc494932ee2527577758f939315ba2c5b (name=test-event-network-local, type=bridge) + 2015-12-23T21:38:25.119625123Z network connect 8b111217944ba0ba844a65b13efcd57dc494932ee2527577758f939315ba2c5b (name=test-event-network-local, container=b4be644031a3d90b400f88ab3d4bdf4dc23adb250e696b6328b85441abe2c54e, type=bridge) diff --git a/integration-cli/docker_cli_build_test.go b/integration-cli/docker_cli_build_test.go index b4dea5f345..207082f201 100644 --- a/integration-cli/docker_cli_build_test.go +++ b/integration-cli/docker_cli_build_test.go @@ -2,7 +2,6 @@ package main import ( "archive/tar" - "bufio" "bytes" "encoding/json" "fmt" @@ -1863,90 +1862,6 @@ func (s *DockerSuite) TestBuildForceRm(c *check.C) { } -// Test that an infinite sleep during a build is killed if the client disconnects. -// This test is fairly hairy because there are lots of ways to race. -// Strategy: -// * Monitor the output of docker events starting from before -// * Run a 1-year-long sleep from a docker build. -// * When docker events sees container start, close the "docker build" command -// * Wait for docker events to emit a dying event. -func (s *DockerSuite) TestBuildCancellationKillsSleep(c *check.C) { - testRequires(c, DaemonIsLinux) - name := "testbuildcancellation" - - observer, err := newEventObserver(c) - c.Assert(err, checker.IsNil) - err = observer.Start() - c.Assert(err, checker.IsNil) - defer observer.Stop() - - // (Note: one year, will never finish) - ctx, err := fakeContext("FROM busybox\nRUN sleep 31536000", nil) - if err != nil { - c.Fatal(err) - } - defer ctx.Close() - - buildCmd := exec.Command(dockerBinary, "build", "-t", name, ".") - buildCmd.Dir = ctx.Dir - - stdoutBuild, err := buildCmd.StdoutPipe() - if err := buildCmd.Start(); err != nil { - c.Fatalf("failed to run build: %s", err) - } - - matchCID := regexp.MustCompile("Running in (.+)") - scanner := bufio.NewScanner(stdoutBuild) - - outputBuffer := new(bytes.Buffer) - var buildID string - for scanner.Scan() { - line := scanner.Text() - outputBuffer.WriteString(line) - outputBuffer.WriteString("\n") - if matches := matchCID.FindStringSubmatch(line); len(matches) > 0 { - buildID = matches[1] - break - } - } - - if buildID == "" { - c.Fatalf("Unable to find build container id in build output:\n%s", outputBuffer.String()) - } - - testActions := map[string]chan bool{ - "start": make(chan bool), - "die": make(chan bool), - } - - go observer.Match(matchEventLine(buildID, "container", testActions)) - - select { - case <-time.After(10 * time.Second): - c.Fatal(observer.TimeoutError(buildID, "start")) - case <-testActions["start"]: - // ignore, done - } - - // Send a kill to the `docker build` command. - // Causes the underlying build to be cancelled due to socket close. - if err := buildCmd.Process.Kill(); err != nil { - c.Fatalf("error killing build command: %s", err) - } - - // Get the exit status of `docker build`, check it exited because killed. - if err := buildCmd.Wait(); err != nil && !isKilled(err) { - c.Fatalf("wait failed during build run: %T %s", err, err) - } - - select { - case <-time.After(10 * time.Second): - c.Fatal(observer.TimeoutError(buildID, "die")) - case <-testActions["die"]: - // ignore, done - } -} - func (s *DockerSuite) TestBuildRm(c *check.C) { testRequires(c, DaemonIsLinux) name := "testbuildrm" diff --git a/integration-cli/docker_cli_build_unix_test.go b/integration-cli/docker_cli_build_unix_test.go index 37b69ef3d2..7d204e1ebb 100644 --- a/integration-cli/docker_cli_build_unix_test.go +++ b/integration-cli/docker_cli_build_unix_test.go @@ -3,12 +3,16 @@ package main import ( + "bufio" + "bytes" "encoding/json" "io/ioutil" "os" "os/exec" "path/filepath" + "regexp" "strings" + "time" "github.com/docker/docker/pkg/integration/checker" "github.com/docker/go-units" @@ -115,5 +119,89 @@ func (s *DockerSuite) TestBuildAddChangeOwnership(c *check.C) { if _, err := buildImageFromContext(name, ctx, true); err != nil { c.Fatalf("build failed to complete for TestBuildAddChangeOwnership: %v", err) } - +} + +// Test that an infinite sleep during a build is killed if the client disconnects. +// This test is fairly hairy because there are lots of ways to race. +// Strategy: +// * Monitor the output of docker events starting from before +// * Run a 1-year-long sleep from a docker build. +// * When docker events sees container start, close the "docker build" command +// * Wait for docker events to emit a dying event. +func (s *DockerSuite) TestBuildCancellationKillsSleep(c *check.C) { + testRequires(c, DaemonIsLinux) + name := "testbuildcancellation" + + observer, err := newEventObserver(c) + c.Assert(err, checker.IsNil) + err = observer.Start() + c.Assert(err, checker.IsNil) + defer observer.Stop() + + // (Note: one year, will never finish) + ctx, err := fakeContext("FROM busybox\nRUN sleep 31536000", nil) + if err != nil { + c.Fatal(err) + } + defer ctx.Close() + + buildCmd := exec.Command(dockerBinary, "build", "-t", name, ".") + buildCmd.Dir = ctx.Dir + + stdoutBuild, err := buildCmd.StdoutPipe() + if err := buildCmd.Start(); err != nil { + c.Fatalf("failed to run build: %s", err) + } + + matchCID := regexp.MustCompile("Running in (.+)") + scanner := bufio.NewScanner(stdoutBuild) + + outputBuffer := new(bytes.Buffer) + var buildID string + for scanner.Scan() { + line := scanner.Text() + outputBuffer.WriteString(line) + outputBuffer.WriteString("\n") + if matches := matchCID.FindStringSubmatch(line); len(matches) > 0 { + buildID = matches[1] + break + } + } + + if buildID == "" { + c.Fatalf("Unable to find build container id in build output:\n%s", outputBuffer.String()) + } + + testActions := map[string]chan bool{ + "start": make(chan bool), + "die": make(chan bool), + } + + matcher := matchEventLine(buildID, "container", testActions) + go observer.Match(matcher) + + select { + case <-time.After(10 * time.Second): + observer.CheckEventError(c, buildID, "start", matcher) + case <-testActions["start"]: + // ignore, done + } + + // Send a kill to the `docker build` command. + // Causes the underlying build to be cancelled due to socket close. + if err := buildCmd.Process.Kill(); err != nil { + c.Fatalf("error killing build command: %s", err) + } + + // Get the exit status of `docker build`, check it exited because killed. + if err := buildCmd.Wait(); err != nil && !isKilled(err) { + c.Fatalf("wait failed during build run: %T %s", err, err) + } + + select { + case <-time.After(10 * time.Second): + observer.CheckEventError(c, buildID, "die", matcher) + case <-testActions["die"]: + // ignore, done + } } diff --git a/integration-cli/docker_cli_events_test.go b/integration-cli/docker_cli_events_test.go index 60bce8a709..aaeb1b0931 100644 --- a/integration-cli/docker_cli_events_test.go +++ b/integration-cli/docker_cli_events_test.go @@ -72,13 +72,25 @@ func (s *DockerSuite) TestEventsContainerFailStartDie(c *check.C) { c.Assert(err, checker.NotNil, check.Commentf("Container run with command blerg should have failed, but it did not, out=%s", out)) out, _ = dockerCmd(c, "events", "--since=0", fmt.Sprintf("--until=%d", daemonTime(c).Unix())) - events := strings.Split(out, "\n") + events := strings.Split(strings.TrimSpace(out), "\n") nEvents := len(events) c.Assert(nEvents, checker.GreaterOrEqualThan, 1) //Missing expected event - c.Assert(parseEventAction(c, events[nEvents-3]), checker.Equals, "start") - c.Assert(parseEventAction(c, events[nEvents-2]), checker.Equals, "die") + actions := eventActionsByIDAndType(c, events, "testeventdie", "container") + + var startEvent bool + var dieEvent bool + for _, a := range actions { + switch a { + case "start": + startEvent = true + case "die": + dieEvent = true + } + } + c.Assert(startEvent, checker.True, check.Commentf("Start event not found: %v\n%v", actions, events)) + c.Assert(dieEvent, checker.True, check.Commentf("Die event not found: %v\n%v", actions, events)) } func (s *DockerSuite) TestEventsLimit(c *check.C) { @@ -150,45 +162,6 @@ func (s *DockerSuite) TestEventsContainerEventsSinceUnixEpoch(c *check.C) { c.Assert(containerEvents[4], checker.Equals, "destroy", check.Commentf(out)) } -func (s *DockerSuite) TestEventsImageUntagDelete(c *check.C) { - testRequires(c, DaemonIsLinux) - - observer, err := newEventObserver(c) - c.Assert(err, checker.IsNil) - err = observer.Start() - c.Assert(err, checker.IsNil) - defer observer.Stop() - - name := "testimageevents" - imageID, err := buildImage(name, - `FROM scratch - MAINTAINER "docker"`, - true) - c.Assert(err, checker.IsNil) - c.Assert(deleteImages(name), checker.IsNil) - - testActions := map[string]chan bool{ - "untag": make(chan bool), - "delete": make(chan bool), - } - - go observer.Match(matchEventLine(imageID, "image", testActions)) - - select { - case <-time.After(10 * time.Second): - c.Fatal(observer.TimeoutError(imageID, "untag")) - case <-testActions["untag"]: - // ignore, done - } - - select { - case <-time.After(10 * time.Second): - c.Fatal(observer.TimeoutError(imageID, "delete")) - case <-testActions["delete"]: - // ignore, done - } -} - func (s *DockerSuite) TestEventsImageTag(c *check.C) { testRequires(c, DaemonIsLinux) time.Sleep(1 * time.Second) // because API has seconds granularity @@ -205,7 +178,6 @@ func (s *DockerSuite) TestEventsImageTag(c *check.C) { event := strings.TrimSpace(events[0]) matches := parseEventText(event) - c.Assert(matches, checker.Not(checker.IsNil)) c.Assert(matchEventID(matches, image), checker.True, check.Commentf("matches: %v\nout:\n%s", matches, out)) c.Assert(matches["action"], checker.Equals, "tag") } @@ -224,7 +196,6 @@ func (s *DockerSuite) TestEventsImagePull(c *check.C) { events := strings.Split(strings.TrimSpace(out), "\n") event := strings.TrimSpace(events[len(events)-1]) matches := parseEventText(event) - c.Assert(matches, checker.Not(checker.IsNil)) c.Assert(matches["id"], checker.Equals, "hello-world:latest") c.Assert(matches["action"], checker.Equals, "pull") @@ -348,7 +319,8 @@ func (s *DockerSuite) TestEventsFilterImageLabels(c *check.C) { "events", fmt.Sprintf("--since=%d", since), fmt.Sprintf("--until=%d", daemonTime(c).Unix()), - "--filter", fmt.Sprintf("label=%s", label)) + "--filter", fmt.Sprintf("label=%s", label), + "--filter", "type=image") events := strings.Split(strings.TrimSpace(out), "\n") @@ -399,46 +371,6 @@ func (s *DockerSuite) TestEventsFilterContainer(c *check.C) { } } -func (s *DockerSuite) TestEventsStreaming(c *check.C) { - testRequires(c, DaemonIsLinux) - - observer, err := newEventObserver(c) - c.Assert(err, checker.IsNil) - err = observer.Start() - c.Assert(err, checker.IsNil) - defer observer.Stop() - - out, _ := dockerCmd(c, "run", "-d", "busybox:latest", "true") - containerID := strings.TrimSpace(out) - - testActions := map[string]chan bool{ - "create": make(chan bool), - "start": make(chan bool), - "die": make(chan bool), - "destroy": make(chan bool), - } - - go observer.Match(matchEventLine(containerID, "container", testActions)) - - select { - case <-time.After(5 * time.Second): - c.Fatal(observer.TimeoutError(containerID, "create/start/die")) - case <-testActions["create"]: - case <-testActions["start"]: - case <-testActions["die"]: - // ignore, done - } - - dockerCmd(c, "rm", containerID) - - select { - case <-time.After(5 * time.Second): - c.Fatal(observer.TimeoutError(containerID, "destroy")) - case <-testActions["destroy"]: - // ignore, done - } -} - func (s *DockerSuite) TestEventsCommit(c *check.C) { testRequires(c, DaemonIsLinux) since := daemonTime(c).Unix() @@ -587,3 +519,69 @@ func (s *DockerRegistrySuite) TestEventsImageFilterPush(c *check.C) { out, _ = dockerCmd(c, "events", "--since=0", "-f", "image="+repoName, "-f", "event=push", "--until="+strconv.Itoa(int(since))) c.Assert(out, checker.Contains, repoName, check.Commentf("Missing 'push' log event for %s", repoName)) } + +func (s *DockerSuite) TestEventsFilterType(c *check.C) { + testRequires(c, DaemonIsLinux) + since := daemonTime(c).Unix() + name := "labelfiltertest" + label := "io.docker.testing=image" + + // Build a test image. + _, err := buildImage(name, fmt.Sprintf(` + FROM busybox:latest + LABEL %s`, label), true) + c.Assert(err, checker.IsNil, check.Commentf("Couldn't create image")) + + dockerCmd(c, "tag", name, "labelfiltertest:tag1") + dockerCmd(c, "tag", name, "labelfiltertest:tag2") + dockerCmd(c, "tag", "busybox:latest", "labelfiltertest:tag3") + + out, _ := dockerCmd( + c, + "events", + fmt.Sprintf("--since=%d", since), + fmt.Sprintf("--until=%d", daemonTime(c).Unix()), + "--filter", fmt.Sprintf("label=%s", label), + "--filter", "type=image") + + events := strings.Split(strings.TrimSpace(out), "\n") + + // 2 events from the "docker tag" command, another one is from "docker build" + c.Assert(events, checker.HasLen, 3, check.Commentf("Events == %s", events)) + for _, e := range events { + c.Assert(e, checker.Contains, "labelfiltertest") + } + + out, _ = dockerCmd( + c, + "events", + fmt.Sprintf("--since=%d", since), + fmt.Sprintf("--until=%d", daemonTime(c).Unix()), + "--filter", fmt.Sprintf("label=%s", label), + "--filter", "type=container") + events = strings.Split(strings.TrimSpace(out), "\n") + + // Events generated by the container that builds the image + c.Assert(events, checker.HasLen, 3, check.Commentf("Events == %s", events)) + + out, _ = dockerCmd( + c, + "events", + fmt.Sprintf("--since=%d", since), + fmt.Sprintf("--until=%d", daemonTime(c).Unix()), + "--filter", "type=network") + events = strings.Split(strings.TrimSpace(out), "\n") + c.Assert(len(events), checker.GreaterOrEqualThan, 1, check.Commentf("Events == %s", events)) +} + +func (s *DockerSuite) TestEventsFilterImageInContainerAction(c *check.C) { + testRequires(c, DaemonIsLinux) + + since := daemonTime(c).Unix() + dockerCmd(c, "run", "--name", "test-container", "-d", "busybox", "true") + waitRun("test-container") + + out, _ := dockerCmd(c, "events", "--filter", "image=busybox", fmt.Sprintf("--since=%d", since), fmt.Sprintf("--until=%d", daemonTime(c).Unix())) + events := strings.Split(strings.TrimSpace(out), "\n") + c.Assert(len(events), checker.GreaterThan, 1, check.Commentf(out)) +} diff --git a/integration-cli/docker_cli_events_unix_test.go b/integration-cli/docker_cli_events_unix_test.go index 4144b6bfce..7afc8fc105 100644 --- a/integration-cli/docker_cli_events_unix_test.go +++ b/integration-cli/docker_cli_events_unix_test.go @@ -203,3 +203,143 @@ func (s *DockerSuite) TestNetworkEvents(c *check.C) { c.Assert(netEvents[2], checker.Equals, "disconnect") c.Assert(netEvents[3], checker.Equals, "destroy") } + +func (s *DockerSuite) TestEventsStreaming(c *check.C) { + testRequires(c, DaemonIsLinux) + + observer, err := newEventObserver(c) + c.Assert(err, checker.IsNil) + err = observer.Start() + c.Assert(err, checker.IsNil) + defer observer.Stop() + + out, _ := dockerCmd(c, "run", "-d", "busybox:latest", "true") + containerID := strings.TrimSpace(out) + + testActions := map[string]chan bool{ + "create": make(chan bool), + "start": make(chan bool), + "die": make(chan bool), + "destroy": make(chan bool), + } + + matcher := matchEventLine(containerID, "container", testActions) + go observer.Match(matcher) + + select { + case <-time.After(5 * time.Second): + observer.CheckEventError(c, containerID, "create", matcher) + case <-testActions["create"]: + // ignore, done + } + + select { + case <-time.After(5 * time.Second): + observer.CheckEventError(c, containerID, "start", matcher) + case <-testActions["start"]: + // ignore, done + } + + select { + case <-time.After(5 * time.Second): + observer.CheckEventError(c, containerID, "die", matcher) + case <-testActions["die"]: + // ignore, done + } + + dockerCmd(c, "rm", containerID) + + select { + case <-time.After(5 * time.Second): + observer.CheckEventError(c, containerID, "destroy", matcher) + case <-testActions["destroy"]: + // ignore, done + } +} + +func (s *DockerSuite) TestEventsImageUntagDelete(c *check.C) { + testRequires(c, DaemonIsLinux) + + observer, err := newEventObserver(c) + c.Assert(err, checker.IsNil) + err = observer.Start() + c.Assert(err, checker.IsNil) + defer observer.Stop() + + name := "testimageevents" + imageID, err := buildImage(name, + `FROM scratch + MAINTAINER "docker"`, + true) + c.Assert(err, checker.IsNil) + c.Assert(deleteImages(name), checker.IsNil) + + testActions := map[string]chan bool{ + "untag": make(chan bool), + "delete": make(chan bool), + } + + matcher := matchEventLine(imageID, "image", testActions) + go observer.Match(matcher) + + select { + case <-time.After(10 * time.Second): + observer.CheckEventError(c, imageID, "untag", matcher) + case <-testActions["untag"]: + // ignore, done + } + + select { + case <-time.After(10 * time.Second): + observer.CheckEventError(c, imageID, "delete", matcher) + case <-testActions["delete"]: + // ignore, done + } +} + +func (s *DockerSuite) TestEventsFilterVolumeAndNetworkType(c *check.C) { + testRequires(c, DaemonIsLinux) + + since := daemonTime(c).Unix() + + dockerCmd(c, "network", "create", "test-event-network-type") + dockerCmd(c, "volume", "create", "--name", "test-event-volume-type") + + out, _ := dockerCmd(c, "events", "--filter", "type=volume", "--filter", "type=network", fmt.Sprintf("--since=%d", since), fmt.Sprintf("--until=%d", daemonTime(c).Unix())) + events := strings.Split(strings.TrimSpace(out), "\n") + c.Assert(len(events), checker.GreaterOrEqualThan, 2, check.Commentf(out)) + + networkActions := eventActionsByIDAndType(c, events, "test-event-network-type", "network") + volumeActions := eventActionsByIDAndType(c, events, "test-event-volume-type", "volume") + + c.Assert(volumeActions[0], checker.Equals, "create") + c.Assert(networkActions[0], checker.Equals, "create") +} + +func (s *DockerSuite) TestEventsFilterVolumeID(c *check.C) { + testRequires(c, DaemonIsLinux) + + since := daemonTime(c).Unix() + + dockerCmd(c, "volume", "create", "--name", "test-event-volume-id") + out, _ := dockerCmd(c, "events", "--filter", "volume=test-event-volume-id", fmt.Sprintf("--since=%d", since), fmt.Sprintf("--until=%d", daemonTime(c).Unix())) + events := strings.Split(strings.TrimSpace(out), "\n") + c.Assert(events, checker.HasLen, 1) + + c.Assert(events[0], checker.Contains, "test-event-volume-id") + c.Assert(events[0], checker.Contains, "driver=local") +} + +func (s *DockerSuite) TestEventsFilterNetworkID(c *check.C) { + testRequires(c, DaemonIsLinux) + + since := daemonTime(c).Unix() + + dockerCmd(c, "network", "create", "test-event-network-local") + out, _ := dockerCmd(c, "events", "--filter", "network=test-event-network-local", fmt.Sprintf("--since=%d", since), fmt.Sprintf("--until=%d", daemonTime(c).Unix())) + events := strings.Split(strings.TrimSpace(out), "\n") + c.Assert(events, checker.HasLen, 1) + + c.Assert(events[0], checker.Contains, "test-event-network-local") + c.Assert(events[0], checker.Contains, "type=bridge") +} diff --git a/integration-cli/events_utils.go b/integration-cli/events_utils.go index 9548d1fff2..8397a57f07 100644 --- a/integration-cli/events_utils.go +++ b/integration-cli/events_utils.go @@ -10,6 +10,7 @@ import ( "strconv" "strings" + "github.com/Sirupsen/logrus" "github.com/docker/docker/pkg/integration/checker" "github.com/go-check/check" ) @@ -27,13 +28,15 @@ var ( ) // eventMatcher is a function that tries to match an event input. -type eventMatcher func(text string) +type eventMatcher func(text string) bool // eventObserver runs an events commands and observes its output. type eventObserver struct { - buffer *bytes.Buffer - command *exec.Cmd - stdout io.Reader + buffer *bytes.Buffer + command *exec.Cmd + scanner *bufio.Scanner + startTime string + disconnectionError error } // newEventObserver creates the observer and initializes the command @@ -45,7 +48,8 @@ func newEventObserver(c *check.C, args ...string) (*eventObserver, error) { // newEventObserverWithBacklog creates a new observer changing the start time of the backlog to return. func newEventObserverWithBacklog(c *check.C, since int64, args ...string) (*eventObserver, error) { - cmdArgs := []string{"events", "--since", strconv.FormatInt(since, 10)} + startTime := strconv.FormatInt(since, 10) + cmdArgs := []string{"events", "--since", startTime} if len(args) > 0 { cmdArgs = append(cmdArgs, args...) } @@ -56,9 +60,10 @@ func newEventObserverWithBacklog(c *check.C, since int64, args ...string) (*even } return &eventObserver{ - buffer: new(bytes.Buffer), - command: eventsCmd, - stdout: stdout, + buffer: new(bytes.Buffer), + command: eventsCmd, + scanner: bufio.NewScanner(stdout), + startTime: startTime, }, nil } @@ -75,43 +80,61 @@ func (e *eventObserver) Stop() { // Match tries to match the events output with a given matcher. func (e *eventObserver) Match(match eventMatcher) { - scanner := bufio.NewScanner(e.stdout) - - for scanner.Scan() { - text := scanner.Text() + for e.scanner.Scan() { + text := e.scanner.Text() e.buffer.WriteString(text) e.buffer.WriteString("\n") match(text) } + + err := e.scanner.Err() + if err == nil { + err = io.EOF + } + + logrus.Debug("EventObserver scanner loop finished: %v", err) + e.disconnectionError = err } -// TimeoutError generates an error for a given containerID and event type. -// It attaches the events command output to the error. -func (e *eventObserver) TimeoutError(id, event string) error { - return fmt.Errorf("failed to observe event `%s` for %s\n%v", event, id, e.output()) -} +func (e *eventObserver) CheckEventError(c *check.C, id, event string, match eventMatcher) { + var foundEvent bool + scannerOut := e.buffer.String() -// output returns the events command output read until now by the Match goroutine. -func (e *eventObserver) output() string { - return e.buffer.String() + if e.disconnectionError != nil { + until := strconv.FormatInt(daemonTime(c).Unix(), 10) + out, _ := dockerCmd(c, "events", "--since", e.startTime, "--until", until) + events := strings.Split(strings.TrimSpace(out), "\n") + for _, e := range events { + if match(e) { + foundEvent = true + break + } + } + scannerOut = out + } + if !foundEvent { + c.Fatalf("failed to observe event `%s` for %s. Disconnection error: %v\nout:\n%v", event, id, e.disconnectionError, scannerOut) + } } // matchEventLine matches a text with the event regular expression. // It returns the action and true if the regular expression matches with the given id and event type. // It returns an empty string and false if there is no match. func matchEventLine(id, eventType string, actions map[string]chan bool) eventMatcher { - return func(text string) { + return func(text string) bool { matches := parseEventText(text) - if matches == nil { - return + if len(matches) == 0 { + return false } if matchIDAndEventType(matches, id, eventType) { if ch, ok := actions[matches["action"]]; ok { close(ch) + return true } } + return false } } @@ -119,12 +142,12 @@ func matchEventLine(id, eventType string, actions map[string]chan bool) eventMat // the matchers in a map. func parseEventText(text string) map[string]string { matches := eventCliRegexp.FindAllStringSubmatch(text, -1) + md := map[string]string{} if len(matches) == 0 { - return nil + return md } names := eventCliRegexp.SubexpNames() - md := map[string]string{} for i, n := range matches[0] { md[names[i]] = n } @@ -135,7 +158,6 @@ func parseEventText(text string) map[string]string { // It fails if the text is not in the event format. func parseEventAction(c *check.C, text string) string { matches := parseEventText(text) - c.Assert(matches, checker.Not(checker.IsNil)) return matches["action"] } @@ -177,10 +199,9 @@ func parseEvents(c *check.C, out, match string) { events := strings.Split(strings.TrimSpace(out), "\n") for _, event := range events { matches := parseEventText(event) - c.Assert(matches, checker.Not(checker.IsNil)) matched, err := regexp.MatchString(match, matches["action"]) c.Assert(err, checker.IsNil) - c.Assert(matched, checker.True) + c.Assert(matched, checker.True, check.Commentf("Matcher: %s did not match %s", match, matches["action"])) } } @@ -188,11 +209,10 @@ func parseEventsWithID(c *check.C, out, match, id string) { events := strings.Split(strings.TrimSpace(out), "\n") for _, event := range events { matches := parseEventText(event) - c.Assert(matches, checker.Not(checker.IsNil)) c.Assert(matchEventID(matches, id), checker.True) matched, err := regexp.MatchString(match, matches["action"]) c.Assert(err, checker.IsNil) - c.Assert(matched, checker.True) + c.Assert(matched, checker.True, check.Commentf("Matcher: %s did not match %s", match, matches["action"])) } }