feat(log): add context fields to lifecycle events (#1007)

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 {

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"?`))
+			})
+		})
+	})
+})

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() {

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)
 		},

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)
 	}
 }