From 697397f28982ac7d12e36a9859abc7147e79f28f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?nils=20m=C3=A5s=C3=A9n?= Date: Sun, 19 Sep 2021 18:07:32 +0200 Subject: [PATCH] feat(log): add context fields to lifecycle events (#1007) --- pkg/container/client.go | 12 +-- pkg/container/client_test.go | 148 +++++++++++++++++++++++++++++++ pkg/container/container_test.go | 122 ------------------------- pkg/container/mocks/ApiServer.go | 17 ++++ pkg/lifecycle/lifecycle.go | 32 ++++--- 5 files changed, 191 insertions(+), 140 deletions(-) create mode 100644 pkg/container/client_test.go diff --git a/pkg/container/client.go b/pkg/container/client.go index 2771733..4e42cba 100644 --- a/pkg/container/client.go +++ b/pkg/container/client.go @@ -361,6 +361,7 @@ func (client dockerClient) RemoveImageByID(id t.ImageID) error { func (client dockerClient) ExecuteCommand(containerID t.ContainerID, command string, timeout int) (SkipUpdate bool, err error) { bg := context.Background() + clog := log.WithField("containerID", containerID) // Create the exec execConfig := types.ExecConfig{ @@ -379,7 +380,7 @@ func (client dockerClient) ExecuteCommand(containerID t.ContainerID, command str Detach: false, }) if attachErr != nil { - log.Errorf("Failed to extract command exec logs: %v", attachErr) + clog.Errorf("Failed to extract command exec logs: %v", attachErr) } // Run the exec @@ -395,7 +396,7 @@ func (client dockerClient) ExecuteCommand(containerID t.ContainerID, command str var writer bytes.Buffer written, err := writer.ReadFrom(response.Reader) if err != nil { - log.Error(err) + clog.Error(err) } else if written > 0 { output = strings.TrimSpace(writer.String()) } @@ -428,9 +429,10 @@ func (client dockerClient) waitForExecOrTimeout(bg context.Context, ID string, e //goland:noinspection GoNilness log.WithFields(log.Fields{ - "exit-code": execInspect.ExitCode, - "exec-id": execInspect.ExecID, - "running": execInspect.Running, + "exit-code": execInspect.ExitCode, + "exec-id": execInspect.ExecID, + "running": execInspect.Running, + "container-id": execInspect.ContainerID, }).Debug("Awaiting timeout or completion") if err != nil { diff --git a/pkg/container/client_test.go b/pkg/container/client_test.go new file mode 100644 index 0000000..01e4c47 --- /dev/null +++ b/pkg/container/client_test.go @@ -0,0 +1,148 @@ +package container + +import ( + "github.com/containrrr/watchtower/pkg/container/mocks" + "github.com/containrrr/watchtower/pkg/filters" + cli "github.com/docker/docker/client" + . "github.com/onsi/ginkgo" + . "github.com/onsi/gomega" + "github.com/onsi/gomega/gbytes" + "github.com/sirupsen/logrus" +) + +var _ = Describe("the client", func() { + var docker *cli.Client + var client Client + BeforeSuite(func() { + server := mocks.NewMockAPIServer() + docker, _ = cli.NewClientWithOpts( + cli.WithHost(server.URL), + cli.WithHTTPClient(server.Client())) + client = dockerClient{ + api: docker, + pullImages: false, + } + }) + It("should return a client for the api", func() { + Expect(client).NotTo(BeNil()) + }) + Describe("WarnOnHeadPullFailed", func() { + containerUnknown := *mockContainerWithImageName("unknown.repo/prefix/imagename:latest") + containerKnown := *mockContainerWithImageName("docker.io/prefix/imagename:latest") + + When("warn on head failure is set to \"always\"", func() { + c := newClientNoAPI(false, false, false, false, false, "always") + It("should always return true", func() { + Expect(c.WarnOnHeadPullFailed(containerUnknown)).To(BeTrue()) + Expect(c.WarnOnHeadPullFailed(containerKnown)).To(BeTrue()) + }) + }) + When("warn on head failure is set to \"auto\"", func() { + c := newClientNoAPI(false, false, false, false, false, "auto") + It("should always return true", func() { + Expect(c.WarnOnHeadPullFailed(containerUnknown)).To(BeFalse()) + }) + It("should", func() { + Expect(c.WarnOnHeadPullFailed(containerKnown)).To(BeTrue()) + }) + }) + When("warn on head failure is set to \"never\"", func() { + c := newClientNoAPI(false, false, false, false, false, "never") + It("should never return true", func() { + Expect(c.WarnOnHeadPullFailed(containerUnknown)).To(BeFalse()) + Expect(c.WarnOnHeadPullFailed(containerKnown)).To(BeFalse()) + }) + }) + }) + + When("listing containers without any filter", func() { + It("should return all available containers", func() { + containers, err := client.ListContainers(filters.NoFilter) + Expect(err).NotTo(HaveOccurred()) + Expect(len(containers) == 2).To(BeTrue()) + }) + }) + When("listing containers with a filter matching nothing", func() { + It("should return an empty array", func() { + filter := filters.FilterByNames([]string{"lollercoaster"}, filters.NoFilter) + containers, err := client.ListContainers(filter) + Expect(err).NotTo(HaveOccurred()) + Expect(len(containers) == 0).To(BeTrue()) + }) + }) + When("listing containers with a watchtower filter", func() { + It("should return only the watchtower container", func() { + containers, err := client.ListContainers(filters.WatchtowerContainersFilter) + Expect(err).NotTo(HaveOccurred()) + Expect(len(containers) == 1).To(BeTrue()) + Expect(containers[0].ImageName()).To(Equal("containrrr/watchtower:latest")) + }) + }) + When(`listing containers with the "include stopped" option`, func() { + It("should return both stopped and running containers", func() { + client = dockerClient{ + api: docker, + pullImages: false, + includeStopped: true, + } + containers, err := client.ListContainers(filters.NoFilter) + Expect(err).NotTo(HaveOccurred()) + Expect(len(containers) > 0).To(BeTrue()) + }) + }) + When(`listing containers with the "include restart" option`, func() { + It("should return both stopped, restarting and running containers", func() { + client = dockerClient{ + api: docker, + pullImages: false, + includeRestarting: true, + } + containers, err := client.ListContainers(filters.NoFilter) + Expect(err).NotTo(HaveOccurred()) + RestartingContainerFound := false + for _, ContainerRunning := range containers { + if ContainerRunning.containerInfo.State.Restarting { + RestartingContainerFound = true + } + } + Expect(RestartingContainerFound).To(BeTrue()) + Expect(RestartingContainerFound).NotTo(BeFalse()) + }) + }) + When(`listing containers without restarting ones`, func() { + It("should not return restarting containers", func() { + client = dockerClient{ + api: docker, + pullImages: false, + includeRestarting: false, + } + containers, err := client.ListContainers(filters.NoFilter) + Expect(err).NotTo(HaveOccurred()) + RestartingContainerFound := false + for _, ContainerRunning := range containers { + if ContainerRunning.containerInfo.State.Restarting { + RestartingContainerFound = true + } + } + Expect(RestartingContainerFound).To(BeFalse()) + Expect(RestartingContainerFound).NotTo(BeTrue()) + }) + }) + Describe(`ExecuteCommand`, func() { + When(`logging`, func() { + It("should include container id field", func() { + // Capture logrus output in buffer + logbuf := gbytes.NewBuffer() + origOut := logrus.StandardLogger().Out + defer logrus.SetOutput(origOut) + logrus.SetOutput(logbuf) + + _, err := client.ExecuteCommand("ex-cont-id", "exec-cmd", 1) + Expect(err).NotTo(HaveOccurred()) + // Note: Since Execute requires opening up a raw TCP stream to the daemon for the output, this will fail + // when using the mock API server. Regardless of the outcome, the log should include the container ID + Eventually(logbuf).Should(gbytes.Say(`containerID="?ex-cont-id"?`)) + }) + }) + }) +}) diff --git a/pkg/container/container_test.go b/pkg/container/container_test.go index 843169b..5204f7d 100644 --- a/pkg/container/container_test.go +++ b/pkg/container/container_test.go @@ -1,136 +1,14 @@ package container import ( - "github.com/containrrr/watchtower/pkg/container/mocks" - "github.com/containrrr/watchtower/pkg/filters" "github.com/docker/docker/api/types" "github.com/docker/docker/api/types/container" - cli "github.com/docker/docker/client" "github.com/docker/go-connections/nat" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" ) var _ = Describe("the container", func() { - Describe("the client", func() { - var docker *cli.Client - var client Client - BeforeSuite(func() { - server := mocks.NewMockAPIServer() - docker, _ = cli.NewClientWithOpts( - cli.WithHost(server.URL), - cli.WithHTTPClient(server.Client())) - client = dockerClient{ - api: docker, - pullImages: false, - } - }) - It("should return a client for the api", func() { - Expect(client).NotTo(BeNil()) - }) - Describe("WarnOnHeadPullFailed", func() { - containerUnknown := *mockContainerWithImageName("unknown.repo/prefix/imagename:latest") - containerKnown := *mockContainerWithImageName("docker.io/prefix/imagename:latest") - - When("warn on head failure is set to \"always\"", func() { - c := newClientNoAPI(false, false, false, false, false, "always") - It("should always return true", func() { - Expect(c.WarnOnHeadPullFailed(containerUnknown)).To(BeTrue()) - Expect(c.WarnOnHeadPullFailed(containerKnown)).To(BeTrue()) - }) - }) - When("warn on head failure is set to \"auto\"", func() { - c := newClientNoAPI(false, false, false, false, false, "auto") - It("should always return true", func() { - Expect(c.WarnOnHeadPullFailed(containerUnknown)).To(BeFalse()) - }) - It("should", func() { - Expect(c.WarnOnHeadPullFailed(containerKnown)).To(BeTrue()) - }) - }) - When("warn on head failure is set to \"never\"", func() { - c := newClientNoAPI(false, false, false, false, false, "never") - It("should never return true", func() { - Expect(c.WarnOnHeadPullFailed(containerUnknown)).To(BeFalse()) - Expect(c.WarnOnHeadPullFailed(containerKnown)).To(BeFalse()) - }) - }) - }) - - When("listing containers without any filter", func() { - It("should return all available containers", func() { - containers, err := client.ListContainers(filters.NoFilter) - Expect(err).NotTo(HaveOccurred()) - Expect(len(containers) == 2).To(BeTrue()) - }) - }) - When("listing containers with a filter matching nothing", func() { - It("should return an empty array", func() { - filter := filters.FilterByNames([]string{"lollercoaster"}, filters.NoFilter) - containers, err := client.ListContainers(filter) - Expect(err).NotTo(HaveOccurred()) - Expect(len(containers) == 0).To(BeTrue()) - }) - }) - When("listing containers with a watchtower filter", func() { - It("should return only the watchtower container", func() { - containers, err := client.ListContainers(filters.WatchtowerContainersFilter) - Expect(err).NotTo(HaveOccurred()) - Expect(len(containers) == 1).To(BeTrue()) - Expect(containers[0].ImageName()).To(Equal("containrrr/watchtower:latest")) - }) - }) - When(`listing containers with the "include stopped" option`, func() { - It("should return both stopped and running containers", func() { - client = dockerClient{ - api: docker, - pullImages: false, - includeStopped: true, - } - containers, err := client.ListContainers(filters.NoFilter) - Expect(err).NotTo(HaveOccurred()) - Expect(len(containers) > 0).To(BeTrue()) - }) - }) - When(`listing containers with the "include restart" option`, func() { - It("should return both stopped, restarting and running containers", func() { - client = dockerClient{ - api: docker, - pullImages: false, - includeRestarting: true, - } - containers, err := client.ListContainers(filters.NoFilter) - Expect(err).NotTo(HaveOccurred()) - RestartingContainerFound := false - for _, ContainerRunning := range containers { - if ContainerRunning.containerInfo.State.Restarting { - RestartingContainerFound = true - } - } - Expect(RestartingContainerFound).To(BeTrue()) - Expect(RestartingContainerFound).NotTo(BeFalse()) - }) - }) - When(`listing containers without restarting ones`, func() { - It("should not return restarting containers", func() { - client = dockerClient{ - api: docker, - pullImages: false, - includeRestarting: false, - } - containers, err := client.ListContainers(filters.NoFilter) - Expect(err).NotTo(HaveOccurred()) - RestartingContainerFound := false - for _, ContainerRunning := range containers { - if ContainerRunning.containerInfo.State.Restarting { - RestartingContainerFound = true - } - } - Expect(RestartingContainerFound).To(BeFalse()) - Expect(RestartingContainerFound).NotTo(BeTrue()) - }) - }) - }) Describe("VerifyConfiguration", func() { When("verifying a container with no image info", func() { It("should return an error", func() { diff --git a/pkg/container/mocks/ApiServer.go b/pkg/container/mocks/ApiServer.go index e192496..96c3921 100644 --- a/pkg/container/mocks/ApiServer.go +++ b/pkg/container/mocks/ApiServer.go @@ -3,6 +3,7 @@ package mocks import ( "encoding/json" "fmt" + "github.com/onsi/ginkgo" "io/ioutil" "net/http" "net/http/httptest" @@ -55,6 +56,22 @@ func NewMockAPIServer() *httptest.Server { response = getMockJSONFromDisk("./mocks/data/image01.json") } else if isRequestFor("sha256:4dbc5f9c07028a985e14d1393e849ea07f68804c4293050d5a641b138db72daa", r) { response = getMockJSONFromDisk("./mocks/data/image02.json") + } else if isRequestFor("containers/ex-cont-id/exec", r) { + response = `{"Id": "ex-exec-id"}` + } else if isRequestFor("exec/ex-exec-id/start", r) { + response = `{"Id": "ex-exec-id"}` + } else if isRequestFor("exec/ex-exec-id/json", r) { + response = `{ + "ExecID": "ex-exec-id", + "ContainerID": "ex-cont-id", + "Running": false, + "ExitCode": 0, + "Pid": 0 + }` + } else { + // Allow ginkgo to correctly capture the failed assertion, even though this is called from a go func + defer ginkgo.GinkgoRecover() + ginkgo.Fail(fmt.Sprintf("mock API server endpoint not supported: %q", r.URL.String())) } _, _ = fmt.Fprintln(w, response) }, diff --git a/pkg/lifecycle/lifecycle.go b/pkg/lifecycle/lifecycle.go index f99913b..d88bb6a 100644 --- a/pkg/lifecycle/lifecycle.go +++ b/pkg/lifecycle/lifecycle.go @@ -30,31 +30,33 @@ func ExecutePostChecks(client container.Client, params types.UpdateParams) { // ExecutePreCheckCommand tries to run the pre-check lifecycle hook for a single container. func ExecutePreCheckCommand(client container.Client, container container.Container) { + clog := log.WithField("container", container.Name()) command := container.GetLifecyclePreCheckCommand() if len(command) == 0 { - log.Debug("No pre-check command supplied. Skipping") + clog.Debug("No pre-check command supplied. Skipping") return } - log.Debug("Executing pre-check command.") + clog.Debug("Executing pre-check command.") _, err := client.ExecuteCommand(container.ID(), command, 1) if err != nil { - log.Error(err) + clog.Error(err) } } // ExecutePostCheckCommand tries to run the post-check lifecycle hook for a single container. func ExecutePostCheckCommand(client container.Client, container container.Container) { + clog := log.WithField("container", container.Name()) command := container.GetLifecyclePostCheckCommand() if len(command) == 0 { - log.Debug("No post-check command supplied. Skipping") + clog.Debug("No post-check command supplied. Skipping") return } - log.Debug("Executing post-check command.") + clog.Debug("Executing post-check command.") _, err := client.ExecuteCommand(container.ID(), command, 1) if err != nil { - log.Error(err) + clog.Error(err) } } @@ -62,38 +64,42 @@ func ExecutePostCheckCommand(client container.Client, container container.Contai func ExecutePreUpdateCommand(client container.Client, container container.Container) (SkipUpdate bool, err error) { timeout := container.PreUpdateTimeout() command := container.GetLifecyclePreUpdateCommand() + clog := log.WithField("container", container.Name()) + if len(command) == 0 { - log.Debug("No pre-update command supplied. Skipping") + clog.Debug("No pre-update command supplied. Skipping") return false, nil } if !container.IsRunning() || container.IsRestarting() { - log.Debug("Container is not running. Skipping pre-update command.") + clog.Debug("Container is not running. Skipping pre-update command.") return false, nil } - log.Debug("Executing pre-update command.") + clog.Debug("Executing pre-update command.") return client.ExecuteCommand(container.ID(), command, timeout) } // ExecutePostUpdateCommand tries to run the post-update lifecycle hook for a single container. func ExecutePostUpdateCommand(client container.Client, newContainerID types.ContainerID) { newContainer, err := client.GetContainer(newContainerID) + if err != nil { - log.Error(err) + log.WithField("containerID", newContainerID.ShortID()).Error(err) return } + clog := log.WithField("container", newContainer.Name()) command := newContainer.GetLifecyclePostUpdateCommand() if len(command) == 0 { - log.Debug("No post-update command supplied. Skipping") + clog.Debug("No post-update command supplied. Skipping") return } - log.Debug("Executing post-update command.") + clog.Debug("Executing post-update command.") _, err = client.ExecuteCommand(newContainerID, command, 1) if err != nil { - log.Error(err) + clog.Error(err) } }