Merge pull request #25681 from vishh/lifecycle-probe-logs

Log output of lifecycle hooks on failure

pkg/kubelet/container/event.go

@@ -62,4 +62,8 @@ const (
 
 	// Config event reason list
 	FailedValidation = "FailedValidation"
+
+	// Lifecycle hooks
+	FailedPostStartHook = "FailedPostStartHook"
+	FailedPreStopHook   = "FailedPreStopHook"
 )

pkg/kubelet/container/helpers.go

@@ -34,7 +34,7 @@ import (
 
 // HandlerRunner runs a lifecycle handler for a container.
 type HandlerRunner interface {
-	Run(containerID ContainerID, pod *api.Pod, container *api.Container, handler *api.Handler) error
+	Run(containerID ContainerID, pod *api.Pod, container *api.Container, handler *api.Handler) (string, error)
 }
 
 // RuntimeHelper wraps kubelet to make container runtime

pkg/kubelet/dockertools/manager.go

@@ -1358,8 +1358,9 @@ func (dm *DockerManager) killContainer(containerID kubecontainer.ContainerID, co
 		go func() {
 			defer close(done)
 			defer utilruntime.HandleCrash()
-			if err := dm.runner.Run(containerID, pod, container, container.Lifecycle.PreStop); err != nil {
+			if msg, err := dm.runner.Run(containerID, pod, container, container.Lifecycle.PreStop); err != nil {
 				glog.Errorf("preStop hook for container %q failed: %v", name, err)
+				dm.generateFailedContainerEvent(containerID, pod.Name, kubecontainer.FailedPreStopHook, msg)
 			}
 		}()
 		select {
@@ -1405,6 +1406,15 @@ func (dm *DockerManager) killContainer(containerID kubecontainer.ContainerID, co
 	return err
 }
 
+func (dm *DockerManager) generateFailedContainerEvent(containerID kubecontainer.ContainerID, podName, reason, message string) {
+	ref, ok := dm.containerRefManager.GetRef(containerID)
+	if !ok {
+		glog.Warningf("No ref for pod '%q'", podName)
+		return
+	}
+	dm.recorder.Event(ref, api.EventTypeWarning, reason, message)
+}
+
 var errNoPodOnContainer = fmt.Errorf("no pod information labels on Docker container")
 
 // containerAndPodFromLabels tries to load the appropriate container info off of a Docker container's labels
@@ -1520,9 +1530,10 @@ func (dm *DockerManager) runContainerInPod(pod *api.Pod, container *api.Containe
 	}
 
 	if container.Lifecycle != nil && container.Lifecycle.PostStart != nil {
-		handlerErr := dm.runner.Run(id, pod, container, container.Lifecycle.PostStart)
+		msg, handlerErr := dm.runner.Run(id, pod, container, container.Lifecycle.PostStart)
 		if handlerErr != nil {
 			err := fmt.Errorf("PostStart handler: %v", handlerErr)
+			dm.generateFailedContainerEvent(id, pod.Name, kubecontainer.FailedPostStartHook, msg)
 			dm.KillContainerInPod(id, container, pod, err.Error(), nil)
 			return kubecontainer.ContainerID{}, err
 		}

pkg/kubelet/lifecycle/fake_handler_runner.go

@@ -35,12 +35,12 @@ func NewFakeHandlerRunner() *FakeHandlerRunner {
 	return &FakeHandlerRunner{HandlerRuns: []string{}}
 }
 
-func (hr *FakeHandlerRunner) Run(containerID kubecontainer.ContainerID, pod *api.Pod, container *api.Container, handler *api.Handler) error {
+func (hr *FakeHandlerRunner) Run(containerID kubecontainer.ContainerID, pod *api.Pod, container *api.Container, handler *api.Handler) (string, error) {
 	hr.Lock()
 	defer hr.Unlock()
 
 	if hr.Err != nil {
-		return hr.Err
+		return "", hr.Err
 	}
 
 	switch {
@@ -51,9 +51,9 @@ func (hr *FakeHandlerRunner) Run(containerID kubecontainer.ContainerID, pod *api
 	case handler.TCPSocket != nil:
 		hr.HandlerRuns = append(hr.HandlerRuns, fmt.Sprintf("tcp-socket on pod: %v, container: %v: %v", format.Pod(pod), container.Name, containerID.String()))
 	default:
-		return fmt.Errorf("Invalid handler: %v", handler)
+		return "", fmt.Errorf("Invalid handler: %v", handler)
 	}
-	return nil
+	return "", nil
 }
 
 func (hr *FakeHandlerRunner) Reset() {

pkg/kubelet/lifecycle/handlers.go

@@ -17,15 +17,18 @@ limitations under the License.
 package lifecycle
 
 import (
+	"bytes"
 	"fmt"
+	"io/ioutil"
 	"net"
+	"net/http"
 	"strconv"
 
-	"bytes"
 	"github.com/golang/glog"
 	"k8s.io/kubernetes/pkg/api"
 	kubecontainer "k8s.io/kubernetes/pkg/kubelet/container"
 	kubetypes "k8s.io/kubernetes/pkg/kubelet/types"
+	"k8s.io/kubernetes/pkg/kubelet/util/format"
 	"k8s.io/kubernetes/pkg/kubelet/util/ioutils"
 	"k8s.io/kubernetes/pkg/types"
 	"k8s.io/kubernetes/pkg/util/intstr"
@@ -49,19 +52,32 @@ func NewHandlerRunner(httpGetter kubetypes.HttpGetter, commandRunner kubecontain
 	}
 }
 
-func (hr *HandlerRunner) Run(containerID kubecontainer.ContainerID, pod *api.Pod, container *api.Container, handler *api.Handler) error {
+func (hr *HandlerRunner) Run(containerID kubecontainer.ContainerID, pod *api.Pod, container *api.Container, handler *api.Handler) (string, error) {
 	switch {
 	case handler.Exec != nil:
-		var buffer bytes.Buffer
+		var (
+			buffer bytes.Buffer
+			msg    string
+		)
 		output := ioutils.WriteCloserWrapper(&buffer)
 		err := hr.commandRunner.ExecInContainer(containerID, handler.Exec.Command, nil, output, output, false)
-		return err
+		if err != nil {
+			msg := fmt.Sprintf("Exec lifecycle hook (%v) for Container %q in Pod %q failed - %q", handler.Exec.Command, container.Name, format.Pod(pod), buffer.String())
+			glog.V(1).Infof(msg)
+		}
+		return msg, err
 	case handler.HTTPGet != nil:
-		return hr.runHTTPHandler(pod, container, handler)
+		msg, err := hr.runHTTPHandler(pod, container, handler)
+		if err != nil {
+			msg := fmt.Sprintf("Http lifecycle hook (%s) for Container %q in Pod %q failed - %q", handler.HTTPGet.Path, container.Name, format.Pod(pod), msg)
+			glog.V(1).Infof(msg)
+		}
+		return msg, err
 	default:
 		err := fmt.Errorf("Invalid handler: %v", handler)
-		glog.Errorf("Cannot run handler: %v", err)
+		msg := fmt.Sprintf("Cannot run handler: %v", err)
-		return err
+		glog.Errorf(msg)
+		return msg, err
 	}
 }
 
@@ -88,16 +104,16 @@ func resolvePort(portReference intstr.IntOrString, container *api.Container) (in
 	return -1, fmt.Errorf("couldn't find port: %v in %v", portReference, container)
 }
 
-func (hr *HandlerRunner) runHTTPHandler(pod *api.Pod, container *api.Container, handler *api.Handler) error {
+func (hr *HandlerRunner) runHTTPHandler(pod *api.Pod, container *api.Container, handler *api.Handler) (string, error) {
 	host := handler.HTTPGet.Host
 	if len(host) == 0 {
 		status, err := hr.containerManager.GetPodStatus(pod.UID, pod.Name, pod.Namespace)
 		if err != nil {
 			glog.Errorf("Unable to get pod info, event handlers may be invalid.")
-			return err
+			return "", err
 		}
 		if status.IP == "" {
-			return fmt.Errorf("failed to find networking container: %v", status)
+			return "", fmt.Errorf("failed to find networking container: %v", status)
 		}
 		host = status.IP
 	}
@@ -108,10 +124,21 @@ func (hr *HandlerRunner) runHTTPHandler(pod *api.Pod, container *api.Container,
 		var err error
 		port, err = resolvePort(handler.HTTPGet.Port, container)
 		if err != nil {
-			return err
+			return "", err
 		}
 	}
 	url := fmt.Sprintf("http://%s/%s", net.JoinHostPort(host, strconv.Itoa(port)), handler.HTTPGet.Path)
-	_, err := hr.httpGetter.Get(url)
+	resp, err := hr.httpGetter.Get(url)
-	return err
+	return getHttpRespBody(resp), err
+}
+
+func getHttpRespBody(resp *http.Response) string {
+	if resp == nil {
+		return ""
+	}
+	defer resp.Body.Close()
+	if bytes, err := ioutil.ReadAll(resp.Body); err == nil {
+		return string(bytes)
+	}
+	return ""
 }

pkg/kubelet/lifecycle/handlers_test.go

@@ -17,9 +17,12 @@ limitations under the License.
 package lifecycle
 
 import (
+	"fmt"
 	"io"
+	"io/ioutil"
 	"net/http"
 	"reflect"
+	"strings"
 	"testing"
 
 	"k8s.io/kubernetes/pkg/api"
@@ -109,7 +112,7 @@ func TestRunHandlerExec(t *testing.T) {
 	pod.ObjectMeta.Name = "podFoo"
 	pod.ObjectMeta.Namespace = "nsFoo"
 	pod.Spec.Containers = []api.Container{container}
-	err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
+	_, err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
 	if err != nil {
 		t.Errorf("unexpected error: %v", err)
 	}
@@ -120,13 +123,14 @@ func TestRunHandlerExec(t *testing.T) {
 }
 
 type fakeHTTP struct {
-	url string
+	url  string
-	err error
+	err  error
+	resp *http.Response
 }
 
 func (f *fakeHTTP) Get(url string) (*http.Response, error) {
 	f.url = url
-	return nil, f.err
+	return f.resp, f.err
 }
 
 func TestRunHandlerHttp(t *testing.T) {
@@ -152,7 +156,7 @@ func TestRunHandlerHttp(t *testing.T) {
 	pod.ObjectMeta.Name = "podFoo"
 	pod.ObjectMeta.Namespace = "nsFoo"
 	pod.Spec.Containers = []api.Container{container}
-	err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
+	_, err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
 
 	if err != nil {
 		t.Errorf("unexpected error: %v", err)
@@ -179,8 +183,45 @@ func TestRunHandlerNil(t *testing.T) {
 	pod.ObjectMeta.Name = podName
 	pod.ObjectMeta.Namespace = podNamespace
 	pod.Spec.Containers = []api.Container{container}
-	err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
+	_, err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
 	if err == nil {
 		t.Errorf("expect error, but got nil")
 	}
 }
+
+func TestRunHandlerHttpFailure(t *testing.T) {
+	expectedErr := fmt.Errorf("fake http error")
+	expectedResp := http.Response{
+		Body: ioutil.NopCloser(strings.NewReader(expectedErr.Error())),
+	}
+	fakeHttp := fakeHTTP{err: expectedErr, resp: &expectedResp}
+	handlerRunner := NewHandlerRunner(&fakeHttp, &fakeContainerCommandRunner{}, nil)
+	containerName := "containerFoo"
+	containerID := kubecontainer.ContainerID{Type: "test", ID: "abc1234"}
+	container := api.Container{
+		Name: containerName,
+		Lifecycle: &api.Lifecycle{
+			PostStart: &api.Handler{
+				HTTPGet: &api.HTTPGetAction{
+					Host: "foo",
+					Port: intstr.FromInt(8080),
+					Path: "bar",
+				},
+			},
+		},
+	}
+	pod := api.Pod{}
+	pod.ObjectMeta.Name = "podFoo"
+	pod.ObjectMeta.Namespace = "nsFoo"
+	pod.Spec.Containers = []api.Container{container}
+	msg, err := handlerRunner.Run(containerID, &pod, &container, container.Lifecycle.PostStart)
+	if err == nil {
+		t.Errorf("expected error: %v", expectedErr)
+	}
+	if msg != expectedErr.Error() {
+		t.Errorf("unexpected error message: %q; expected %q", msg, expectedErr)
+	}
+	if fakeHttp.url != "http://foo:8080/bar" {
+		t.Errorf("unexpected url: %s", fakeHttp.url)
+	}
+}

pkg/kubelet/rkt/rkt.go

@@ -1222,7 +1222,16 @@ func (r *Runtime) RunPod(pod *api.Pod, pullSecrets []api.Secret) error {
 
 func (r *Runtime) runPreStopHook(containerID kubecontainer.ContainerID, pod *api.Pod, container *api.Container) error {
 	glog.V(4).Infof("rkt: Running pre-stop hook for container %q of pod %q", container.Name, format.Pod(pod))
-	return r.runner.Run(containerID, pod, container, container.Lifecycle.PreStop)
+	msg, err := r.runner.Run(containerID, pod, container, container.Lifecycle.PreStop)
+	if err != nil {
+		ref, ok := r.containerRefManager.GetRef(containerID)
+		if !ok {
+			glog.Warningf("No ref for container %q", containerID)
+		} else {
+			r.recorder.Eventf(ref, api.EventTypeWarning, kubecontainer.FailedPreStopHook, msg)
+		}
+	}
+	return err
 }
 
 func (r *Runtime) runPostStartHook(containerID kubecontainer.ContainerID, pod *api.Pod, container *api.Container) error {
@@ -1253,7 +1262,16 @@ func (r *Runtime) runPostStartHook(containerID kubecontainer.ContainerID, pod *a
 		return fmt.Errorf("rkt: Pod %q doesn't become running in %v: %v", format.Pod(pod), timeout, err)
 	}
 
-	return r.runner.Run(containerID, pod, container, container.Lifecycle.PostStart)
+	msg, err := r.runner.Run(containerID, pod, container, container.Lifecycle.PostStart)
+	if err != nil {
+		ref, ok := r.containerRefManager.GetRef(containerID)
+		if !ok {
+			glog.Warningf("No ref for container %q", containerID)
+		} else {
+			r.recorder.Eventf(ref, api.EventTypeWarning, kubecontainer.FailedPostStartHook, msg)
+		}
+	}
+	return err
 }
 
 type lifecycleHookType string