From 1aff115f444dbe9661ee3826e24bf7e380056854 Mon Sep 17 00:00:00 2001 From: gmarek Date: Tue, 11 Oct 2016 16:46:33 +0200 Subject: [PATCH] Make logging function injectable in RCConfig --- test/e2e/daemon_restart.go | 2 +- test/e2e/density.go | 4 +- test/e2e/e2e.go | 4 +- test/e2e/framework/framework.go | 6 +- test/e2e/framework/kubelet_stats.go | 4 +- test/e2e/framework/metrics_util.go | 2 +- test/e2e/framework/util.go | 112 ++++++++++++++-------------- 7 files changed, 65 insertions(+), 69 deletions(-) diff --git a/test/e2e/daemon_restart.go b/test/e2e/daemon_restart.go index 61d84b758c..4fad69c8e1 100644 --- a/test/e2e/daemon_restart.go +++ b/test/e2e/daemon_restart.go @@ -312,7 +312,7 @@ var _ = framework.KubeDescribe("DaemonRestart [Disruptive]", func() { } postRestarts, badNodes := getContainerRestarts(f.Client, ns, labelSelector) if postRestarts != preRestarts { - framework.DumpNodeDebugInfo(f.Client, badNodes) + framework.DumpNodeDebugInfo(f.Client, badNodes, framework.Logf) framework.Failf("Net container restart count went from %v -> %v after kubelet restart on nodes %v \n\n %+v", preRestarts, postRestarts, badNodes, tracker) } }) diff --git a/test/e2e/density.go b/test/e2e/density.go index 0c0296a167..fb2421d62c 100644 --- a/test/e2e/density.go +++ b/test/e2e/density.go @@ -172,11 +172,11 @@ func logPodStartupStatus(c *client.Client, expectedPods int, ns string, observed case <-ticker.C: pods := podStore.List() startupStatus := framework.ComputeRCStartupStatus(pods, expectedPods) - startupStatus.Print("Density") + framework.Logf(startupStatus.String("Density")) case <-stopCh: pods := podStore.List() startupStatus := framework.ComputeRCStartupStatus(pods, expectedPods) - startupStatus.Print("Density") + framework.Logf(startupStatus.String("Density")) return } } diff --git a/test/e2e/e2e.go b/test/e2e/e2e.go index 32a18984bf..f07c125828 100644 --- a/test/e2e/e2e.go +++ b/test/e2e/e2e.go @@ -123,7 +123,7 @@ var _ = ginkgo.SynchronizedBeforeSuite(func() []byte { podStartupTimeout := framework.TestContext.SystemPodsStartupTimeout if err := framework.WaitForPodsRunningReady(c, api.NamespaceSystem, int32(framework.TestContext.MinStartupPods), podStartupTimeout, framework.ImagePullerLabels); err != nil { framework.DumpAllNamespaceInfo(c, clientset, api.NamespaceSystem) - framework.LogFailedContainers(c, api.NamespaceSystem) + framework.LogFailedContainers(c, api.NamespaceSystem, framework.Logf) framework.RunKubernetesServiceTestContainer(c, api.NamespaceDefault) framework.Failf("Error waiting for all pods to be running and ready: %v", err) } @@ -139,7 +139,7 @@ var _ = ginkgo.SynchronizedBeforeSuite(func() []byte { // Dump the output of the nethealth containers only once per run if framework.TestContext.DumpLogsOnFailure { framework.Logf("Dumping network health container logs from all nodes") - framework.LogContainersInPodsWithLabels(c, api.NamespaceSystem, framework.ImagePullerLabels, "nethealth") + framework.LogContainersInPodsWithLabels(c, api.NamespaceSystem, framework.ImagePullerLabels, "nethealth", framework.Logf) } // Reference common test to make the import valid. diff --git a/test/e2e/framework/framework.go b/test/e2e/framework/framework.go index 0181df9ee3..3f20465cac 100644 --- a/test/e2e/framework/framework.go +++ b/test/e2e/framework/framework.go @@ -377,16 +377,16 @@ func (f *Framework) AfterEach() { // Pass both unversioned client and and versioned clientset, till we have removed all uses of the unversioned client. DumpAllNamespaceInfo(f.Client, f.ClientSet_1_5, f.Namespace.Name) By(fmt.Sprintf("Dumping a list of prepulled images on each node")) - LogContainersInPodsWithLabels(f.Client, api.NamespaceSystem, ImagePullerLabels, "image-puller") + LogContainersInPodsWithLabels(f.Client, api.NamespaceSystem, ImagePullerLabels, "image-puller", Logf) if f.federated { // Dump federation events in federation namespace. DumpEventsInNamespace(func(opts v1.ListOptions, ns string) (*v1.EventList, error) { return f.FederationClientset_1_5.Core().Events(ns).List(opts) }, f.FederationNamespace.Name) // Print logs of federation control plane pods (federation-apiserver and federation-controller-manager) - LogPodsWithLabels(f.Client, "federation", map[string]string{"app": "federated-cluster"}) + LogPodsWithLabels(f.Client, "federation", map[string]string{"app": "federated-cluster"}, Logf) // Print logs of kube-dns pod - LogPodsWithLabels(f.Client, "kube-system", map[string]string{"k8s-app": "kube-dns"}) + LogPodsWithLabels(f.Client, "kube-system", map[string]string{"k8s-app": "kube-dns"}, Logf) } } diff --git a/test/e2e/framework/kubelet_stats.go b/test/e2e/framework/kubelet_stats.go index eeeb746c06..e1bce110ec 100644 --- a/test/e2e/framework/kubelet_stats.go +++ b/test/e2e/framework/kubelet_stats.go @@ -256,7 +256,7 @@ func getNodeRuntimeOperationErrorRate(c *client.Client, node string) (NodeRuntim } // HighLatencyKubeletOperations logs and counts the high latency metrics exported by the kubelet server via /metrics. -func HighLatencyKubeletOperations(c *client.Client, threshold time.Duration, nodeName string) (KubeletLatencyMetrics, error) { +func HighLatencyKubeletOperations(c *client.Client, threshold time.Duration, nodeName string, logFunc func(fmt string, args ...interface{})) (KubeletLatencyMetrics, error) { ms, err := getKubeletMetrics(c, nodeName) if err != nil { return KubeletLatencyMetrics{}, err @@ -264,7 +264,7 @@ func HighLatencyKubeletOperations(c *client.Client, threshold time.Duration, nod latencyMetrics := GetKubeletLatencyMetrics(ms) sort.Sort(latencyMetrics) var badMetrics KubeletLatencyMetrics - Logf("\nLatency metrics for node %v", nodeName) + logFunc("\nLatency metrics for node %v", nodeName) for _, m := range latencyMetrics { if m.Latency > threshold { badMetrics = append(badMetrics, m) diff --git a/test/e2e/framework/metrics_util.go b/test/e2e/framework/metrics_util.go index f21379552e..8ba7a389aa 100644 --- a/test/e2e/framework/metrics_util.go +++ b/test/e2e/framework/metrics_util.go @@ -463,7 +463,7 @@ func LogSuspiciousLatency(latencyData []PodLatencyData, latencyDataLag []PodLate } for _, l := range latencyData { if l.Latency > NodeStartupThreshold { - HighLatencyKubeletOperations(c, 1*time.Second, l.Node) + HighLatencyKubeletOperations(c, 1*time.Second, l.Node, Logf) } } Logf("Approx throughput: %v pods/min", diff --git a/test/e2e/framework/util.go b/test/e2e/framework/util.go index f809b8c6f6..e1cfd5e7cf 100644 --- a/test/e2e/framework/util.go +++ b/test/e2e/framework/util.go @@ -334,6 +334,16 @@ type RCConfig struct { // If set to false starting RC will print progress, otherwise only errors will be printed. Silent bool + + // If set this function will be used to print log lines instead of glog. + LogFunc func(fmt string, args ...interface{}) +} + +func (rc *RCConfig) RCConfigLog(fmt string, args ...interface{}) { + if rc.LogFunc != nil { + rc.LogFunc(fmt, args...) + } + glog.Infof(fmt, args...) } type DeploymentConfig struct { @@ -609,7 +619,7 @@ func WaitForPodsSuccess(c *client.Client, ns string, successPodLabels map[string return false, nil }) != nil { logPodStates(badPods) - LogPodsWithLabels(c, ns, successPodLabels) + LogPodsWithLabels(c, ns, successPodLabels, Logf) return errors.New(errorBadPodsStates(badPods, desiredPods, ns, "SUCCESS", timeout)) } @@ -753,7 +763,7 @@ func RunKubernetesServiceTestContainer(c *client.Client, ns string) { } } -func kubectlLogPod(c *client.Client, pod api.Pod, containerNameSubstr string) { +func kubectlLogPod(c *client.Client, pod api.Pod, containerNameSubstr string, logFunc func(ftm string, args ...interface{})) { for _, container := range pod.Spec.Containers { if strings.Contains(container.Name, containerNameSubstr) { // Contains() matches all strings if substr is empty @@ -761,49 +771,49 @@ func kubectlLogPod(c *client.Client, pod api.Pod, containerNameSubstr string) { if err != nil { logs, err = getPreviousPodLogs(c, pod.Namespace, pod.Name, container.Name) if err != nil { - Logf("Failed to get logs of pod %v, container %v, err: %v", pod.Name, container.Name, err) + logFunc("Failed to get logs of pod %v, container %v, err: %v", pod.Name, container.Name, err) } } By(fmt.Sprintf("Logs of %v/%v:%v on node %v", pod.Namespace, pod.Name, container.Name, pod.Spec.NodeName)) - Logf("%s : STARTLOG\n%s\nENDLOG for container %v:%v:%v", containerNameSubstr, logs, pod.Namespace, pod.Name, container.Name) + logFunc("%s : STARTLOG\n%s\nENDLOG for container %v:%v:%v", containerNameSubstr, logs, pod.Namespace, pod.Name, container.Name) } } } -func LogFailedContainers(c *client.Client, ns string) { +func LogFailedContainers(c *client.Client, ns string, logFunc func(ftm string, args ...interface{})) { podList, err := c.Pods(ns).List(api.ListOptions{}) if err != nil { - Logf("Error getting pods in namespace '%s': %v", ns, err) + logFunc("Error getting pods in namespace '%s': %v", ns, err) return } - Logf("Running kubectl logs on non-ready containers in %v", ns) + logFunc("Running kubectl logs on non-ready containers in %v", ns) for _, pod := range podList.Items { if res, err := PodRunningReady(&pod); !res || err != nil { - kubectlLogPod(c, pod, "") + kubectlLogPod(c, pod, "", Logf) } } } -func LogPodsWithLabels(c *client.Client, ns string, match map[string]string) { +func LogPodsWithLabels(c *client.Client, ns string, match map[string]string, logFunc func(ftm string, args ...interface{})) { podList, err := c.Pods(ns).List(api.ListOptions{LabelSelector: labels.SelectorFromSet(match)}) if err != nil { - Logf("Error getting pods in namespace %q: %v", ns, err) + logFunc("Error getting pods in namespace %q: %v", ns, err) return } - Logf("Running kubectl logs on pods with labels %v in %v", match, ns) + logFunc("Running kubectl logs on pods with labels %v in %v", match, ns) for _, pod := range podList.Items { - kubectlLogPod(c, pod, "") + kubectlLogPod(c, pod, "", logFunc) } } -func LogContainersInPodsWithLabels(c *client.Client, ns string, match map[string]string, containerSubstr string) { +func LogContainersInPodsWithLabels(c *client.Client, ns string, match map[string]string, containerSubstr string, logFunc func(ftm string, args ...interface{})) { podList, err := c.Pods(ns).List(api.ListOptions{LabelSelector: labels.SelectorFromSet(match)}) if err != nil { Logf("Error getting pods in namespace %q: %v", ns, err) return } for _, pod := range podList.Items { - kubectlLogPod(c, pod, containerSubstr) + kubectlLogPod(c, pod, containerSubstr, logFunc) } } @@ -2346,13 +2356,14 @@ type podInfo struct { type PodDiff map[string]*podInfo // Print formats and prints the give PodDiff. -func (p PodDiff) Print(ignorePhases sets.String) { +func (p PodDiff) String(ignorePhases sets.String) string { + ret := "" for name, info := range p { if ignorePhases.Has(info.phase) { continue } if info.phase == nonExist { - Logf("Pod %v was deleted, had phase %v and host %v", name, info.oldPhase, info.oldHostname) + ret += fmt.Sprintf("Pod %v was deleted, had phase %v and host %v\n", name, info.oldPhase, info.oldHostname) continue } phaseChange, hostChange := false, false @@ -2374,9 +2385,10 @@ func (p PodDiff) Print(ignorePhases sets.String) { } } if phaseChange || hostChange { - Logf(msg) + ret += msg + "\n" } } + return ret } // Diff computes a PodDiff given 2 lists of pods. @@ -2448,7 +2460,7 @@ func (config *DeploymentConfig) create() error { if err != nil { return fmt.Errorf("Error creating deployment: %v", err) } - Logf("Created deployment with name: %v, namespace: %v, replica count: %v", deployment.Name, config.Namespace, deployment.Spec.Replicas) + config.RCConfigLog("Created deployment with name: %v, namespace: %v, replica count: %v", deployment.Name, config.Namespace, deployment.Spec.Replicas) return nil } @@ -2501,7 +2513,7 @@ func (config *ReplicaSetConfig) create() error { if err != nil { return fmt.Errorf("Error creating replica set: %v", err) } - Logf("Created replica set with name: %v, namespace: %v, replica count: %v", rs.Name, config.Namespace, rs.Spec.Replicas) + config.RCConfigLog("Created replica set with name: %v, namespace: %v, replica count: %v", rs.Name, config.Namespace, rs.Spec.Replicas) return nil } @@ -2559,7 +2571,7 @@ func (config *RCConfig) create() error { if err != nil { return fmt.Errorf("Error creating replication controller: %v", err) } - Logf("Created replication controller with name: %v, namespace: %v, replica count: %v", rc.Name, config.Namespace, rc.Spec.Replicas) + config.RCConfigLog("Created replication controller with name: %v, namespace: %v, replica count: %v", rc.Name, config.Namespace, rc.Spec.Replicas) return nil } @@ -2633,8 +2645,8 @@ type RCStartupStatus struct { ContainerRestartNodes sets.String } -func (s *RCStartupStatus) Print(name string) { - Logf("%v Pods: %d out of %d created, %d running, %d pending, %d waiting, %d inactive, %d terminating, %d unknown, %d runningButNotReady ", +func (s *RCStartupStatus) String(name string) string { + return fmt.Sprintf("%v Pods: %d out of %d created, %d running, %d pending, %d waiting, %d inactive, %d terminating, %d unknown, %d runningButNotReady ", name, len(s.Created), s.Expected, s.Running, s.Pending, s.Waiting, s.Inactive, s.Terminating, s.Unknown, s.RunningButNotReady) } @@ -2719,7 +2731,7 @@ func (config *RCConfig) start() error { *config.CreatedPods = pods } if !config.Silent { - startupStatus.Print(config.Name) + config.RCConfigLog(startupStatus.String(config.Name)) } promPushRunningPending(startupStatus.Running, startupStatus.Pending) @@ -2729,9 +2741,9 @@ func (config *RCConfig) start() error { } if startupStatus.FailedContainers > maxContainerFailures { - DumpNodeDebugInfo(config.Client, startupStatus.ContainerRestartNodes.List()) + DumpNodeDebugInfo(config.Client, startupStatus.ContainerRestartNodes.List(), config.RCConfigLog) // Get the logs from the failed containers to help diagnose what caused them to fail - LogFailedContainers(config.Client, config.Namespace) + LogFailedContainers(config.Client, config.Namespace, config.RCConfigLog) return fmt.Errorf("%d containers failed which is more than allowed %d", startupStatus.FailedContainers, maxContainerFailures) } if len(pods) < len(oldPods) || len(pods) > config.Replicas { @@ -2741,8 +2753,8 @@ func (config *RCConfig) start() error { // pod is unhealthy, so replication controller creates another to take its place // - diagnose by comparing the previous "2 Pod states" lines for inactive pods errorStr := fmt.Sprintf("Number of reported pods for %s changed: %d vs %d", config.Name, len(pods), len(oldPods)) - Logf("%v, pods that changed since the last iteration:", errorStr) - Diff(oldPods, pods).Print(sets.NewString()) + config.RCConfigLog("%v, pods that changed since the last iteration:", errorStr) + config.RCConfigLog(Diff(oldPods, pods).String(sets.NewString())) return fmt.Errorf(errorStr) } @@ -2753,7 +2765,6 @@ func (config *RCConfig) start() error { oldRunning = startupStatus.Running if time.Since(lastChange) > timeout { - dumpPodDebugInfo(config.Client, pods) break } } @@ -2764,10 +2775,10 @@ func (config *RCConfig) start() error { if pods, err := config.Client.Pods(api.NamespaceAll).List(options); err == nil { for _, pod := range pods.Items { - Logf("Pod %s\t%s\t%s\t%s", pod.Name, pod.Spec.NodeName, pod.Status.Phase, pod.DeletionTimestamp) + config.RCConfigLog("Pod %s\t%s\t%s\t%s", pod.Name, pod.Spec.NodeName, pod.Status.Phase, pod.DeletionTimestamp) } } else { - Logf("Can't list pod debug info: %v", err) + config.RCConfigLog("Can't list pod debug info: %v", err) } return fmt.Errorf("Only %d pods started out of %d", oldRunning, config.Replicas) } @@ -2800,21 +2811,6 @@ func StartPods(c *client.Client, replicas int, namespace string, podNamePrefix s } } -func dumpPodDebugInfo(c *client.Client, pods []*api.Pod) { - badNodes := sets.NewString() - for _, p := range pods { - if p.Status.Phase != api.PodRunning { - if p.Spec.NodeName != "" { - Logf("Pod %v assigned to host %v (IP: %v) in %v", p.Name, p.Spec.NodeName, p.Status.HostIP, p.Status.Phase) - badNodes.Insert(p.Spec.NodeName) - } else { - Logf("Pod %v still unassigned", p.Name) - } - } - } - DumpNodeDebugInfo(c, badNodes.List()) -} - type EventsLister func(opts v1.ListOptions, ns string) (*v1.EventList, error) func DumpEventsInNamespace(eventsLister EventsLister, namespace string) { @@ -2889,41 +2885,41 @@ func dumpAllNodeInfo(c *client.Client) { for ix := range nodes.Items { names[ix] = nodes.Items[ix].Name } - DumpNodeDebugInfo(c, names) + DumpNodeDebugInfo(c, names, Logf) } -func DumpNodeDebugInfo(c *client.Client, nodeNames []string) { +func DumpNodeDebugInfo(c *client.Client, nodeNames []string, logFunc func(fmt string, args ...interface{})) { for _, n := range nodeNames { - Logf("\nLogging node info for node %v", n) + logFunc("\nLogging node info for node %v", n) node, err := c.Nodes().Get(n) if err != nil { - Logf("Error getting node info %v", err) + logFunc("Error getting node info %v", err) } - Logf("Node Info: %v", node) + logFunc("Node Info: %v", node) - Logf("\nLogging kubelet events for node %v", n) + logFunc("\nLogging kubelet events for node %v", n) for _, e := range getNodeEvents(c, n) { - Logf("source %v type %v message %v reason %v first ts %v last ts %v, involved obj %+v", + logFunc("source %v type %v message %v reason %v first ts %v last ts %v, involved obj %+v", e.Source, e.Type, e.Message, e.Reason, e.FirstTimestamp, e.LastTimestamp, e.InvolvedObject) } - Logf("\nLogging pods the kubelet thinks is on node %v", n) + logFunc("\nLogging pods the kubelet thinks is on node %v", n) podList, err := GetKubeletPods(c, n) if err != nil { - Logf("Unable to retrieve kubelet pods for node %v", n) + logFunc("Unable to retrieve kubelet pods for node %v", n) continue } for _, p := range podList.Items { - Logf("%v started at %v (%d+%d container statuses recorded)", p.Name, p.Status.StartTime, len(p.Status.InitContainerStatuses), len(p.Status.ContainerStatuses)) + logFunc("%v started at %v (%d+%d container statuses recorded)", p.Name, p.Status.StartTime, len(p.Status.InitContainerStatuses), len(p.Status.ContainerStatuses)) for _, c := range p.Status.InitContainerStatuses { - Logf("\tInit container %v ready: %v, restart count %v", + logFunc("\tInit container %v ready: %v, restart count %v", c.Name, c.Ready, c.RestartCount) } for _, c := range p.Status.ContainerStatuses { - Logf("\tContainer %v ready: %v, restart count %v", + logFunc("\tContainer %v ready: %v, restart count %v", c.Name, c.Ready, c.RestartCount) } } - HighLatencyKubeletOperations(c, 10*time.Second, n) + HighLatencyKubeletOperations(c, 10*time.Second, n, logFunc) // TODO: Log node resource info } }