[JENKINS-74992] Print relevant pod provisioning events in build logs

src/main/java/org/csanchez/jenkins/plugins/kubernetes/KubernetesLauncher.java

@@ -42,13 +42,15 @@
 import io.fabric8.kubernetes.api.model.Pod;
 import io.fabric8.kubernetes.client.KubernetesClient;
 import io.fabric8.kubernetes.client.KubernetesClientException;
+import io.fabric8.kubernetes.client.informers.SharedIndexInformer;
 import java.io.IOException;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collection;
 import java.util.Collections;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import java.util.logging.Logger;
@@ -57,6 +59,7 @@
 import org.apache.commons.lang.StringUtils;
 import org.csanchez.jenkins.plugins.kubernetes.pod.decorator.PodDecoratorException;
 import org.csanchez.jenkins.plugins.kubernetes.pod.retention.Reaper;
+import org.csanchez.jenkins.plugins.kubernetes.watch.PodStatusEventHandler;
 import org.kohsuke.stapler.DataBoundConstructor;
 
 /**
@@ -73,6 +76,9 @@ public class KubernetesLauncher extends JNLPLauncher {
 
     private volatile boolean launched = false;
 
+    // namespace -> informer
+    private static final Map<String, SharedIndexInformer<Pod>> informers = new ConcurrentHashMap<>();
+
     /**
      * Provisioning exception if any.
      */
@@ -145,6 +151,15 @@ public synchronized void launch(SlaveComputer computer, TaskListener listener) {
                     .orElse(null);
             node.setNamespace(namespace);
 
+            // register a namespace informer (if not registered yet) show relevant pod events in build logs
+            if (informers.get(namespace) == null) {
+                SharedIndexInformer<Pod> inform = client.pods()
+                        .inNamespace(namespace)
+                        .inform(new PodStatusEventHandler(), TimeUnit.SECONDS.toMillis(30));
+                LOGGER.info("Registered informer to watch events on namespace: " + namespace);
+                informers.put(namespace, inform);
+            }
+
             // if the controller was interrupted after creating the pod but before it connected back, then
             // the pod might already exist and the creating logic must be skipped.
             Pod existingPod =

src/main/java/org/csanchez/jenkins/plugins/kubernetes/watch/PodStatusEventHandler.java

@@ -0,0 +1,85 @@
+package org.csanchez.jenkins.plugins.kubernetes.watch;
+
+import hudson.model.Node;
+import hudson.model.TaskListener;
+import hudson.slaves.SlaveComputer;
+import io.fabric8.kubernetes.api.model.ContainerState;
+import io.fabric8.kubernetes.api.model.ContainerStatus;
+import io.fabric8.kubernetes.api.model.Pod;
+import io.fabric8.kubernetes.api.model.PodCondition;
+import io.fabric8.kubernetes.client.informers.ResourceEventHandler;
+import java.util.Optional;
+import java.util.logging.Logger;
+import jenkins.model.Jenkins;
+import org.csanchez.jenkins.plugins.kubernetes.KubernetesSlave;
+
+/**
+ * Process pod events and print relevant information in build logs.
+ * Registered as an informer in {@link org.csanchez.jenkins.plugins.kubernetes.KubernetesLauncher#launch(SlaveComputer, TaskListener)}).
+ */
+public class PodStatusEventHandler implements ResourceEventHandler<Pod> {
+
+    private static final Logger LOGGER = Logger.getLogger(PodStatusEventHandler.class.getName());
+
+    @Override
+    public void onUpdate(Pod unused, Pod pod) {
+        Optional<Node> found = Jenkins.get().getNodes().stream()
+                .filter(n -> n.getNodeName().equals(pod.getMetadata().getName()))
+                .findFirst();
+        if (found.isPresent()) {
+            final StringBuilder sb = new StringBuilder();
+            pod.getStatus().getContainerStatuses().forEach(s -> sb.append(formatContainerStatus(s)));
+            pod.getStatus().getConditions().forEach(c -> sb.append(formatPodStatus(c, pod.getStatus().getPhase())));
+            if (!sb.toString().isEmpty()) {
+                ((KubernetesSlave) found.get())
+                        .getRunListener()
+                        .getLogger()
+                        .println("[PodInfo] " + pod.getMetadata().getName() + sb);
+            }
+        } else {
+            LOGGER.fine(() -> "Event received for non-existent node: ["
+                    + pod.getMetadata().getName() + "]");
+        }
+    }
+
+    private String formatPodStatus(PodCondition c, String phase) {
+        if (c.getReason() == null) {
+            // not interesting
+            return "";
+        }
+        return String.format("%n\tPod [%s][%s] %s", phase, c.getReason(), c.getMessage());
+    }
+
+    private String formatContainerStatus(ContainerStatus s) {
+        ContainerState state = s.getState();
+        if (state.getRunning() != null) {
+            // don't care about running
+            return "";
+        }
+        StringBuilder sb = new StringBuilder();
+        sb.append(String.format("%n\tContainer [%s]", s.getName()));
+        if (state.getTerminated() != null) {
+            String message = state.getTerminated().getMessage();
+            sb.append(String.format(
+                    " terminated [%s] %s",
+                    state.getTerminated().getReason(), message != null ? message : "No message"));
+        }
+        if (state.getWaiting() != null) {
+            String message = state.getWaiting().getMessage();
+            sb.append(String.format(
+                    " waiting [%s] %s",
+                    state.getWaiting().getReason(), message != null ? message : "No message"));
+        }
+        return sb.toString();
+    }
+
+    @Override
+    public void onDelete(Pod pod, boolean deletedFinalStateUnknown) {
+        // no-op
+    }
+
+    @Override
+    public void onAdd(Pod pod) {
+        // no-op
+    }
+}

src/test/java/org/csanchez/jenkins/plugins/kubernetes/pipeline/PodProvisioningStatusLogsTest.java

@@ -0,0 +1,38 @@
+package org.csanchez.jenkins.plugins.kubernetes.pipeline;
+
+import hudson.model.Result;
+import org.junit.Test;
+
+import static org.junit.Assert.assertNotNull;
+
+public class PodProvisioningStatusLogsTest extends AbstractKubernetesPipelineTest {
+
+    @Test
+    public void podStatusErrorLogs() throws Exception {
+        assertNotNull(createJobThenScheduleRun());
+        // pod not schedulable
+        // build never finishes, so just checking the message and killing
+        r.waitForMessage("Pod [Pending][Unschedulable] 0/1 nodes are available", b);
+        b.doKill();
+        r.waitUntilNoActivity();
+    }
+
+    @Test
+    public void podStatusNoErrorLogs() throws Exception {
+        assertNotNull(createJobThenScheduleRun());
+        r.assertBuildStatusSuccess(r.waitForCompletion(b));
+        // regular logs when starting containers
+        r.assertLogContains("Container [jnlp] waiting [ContainerCreating]", b);
+        r.assertLogContains("Pod [Pending][ContainersNotReady] containers with unready status: [shell jnlp]", b);
+    }
+
+    @Test
+    public void containerStatusErrorLogs() throws Exception {
+        assertNotNull(createJobThenScheduleRun());
+        r.assertBuildStatus(Result.ABORTED, r.waitForCompletion(b));
+        // error starting container
+        r.assertLogContains("Container [shell] terminated [StartError]", b);
+        r.assertLogContains("exec: \"oops\": executable file not found", b);
+        r.assertLogContains("Pod [Running][ContainersNotReady] containers with unready status: [shell]", b);
+    }
+}

src/test/resources/org/csanchez/jenkins/plugins/kubernetes/pipeline/containerStatusErrorLogs.groovy

@@ -0,0 +1,26 @@
+//noinspection GrPackage
+pipeline {
+    agent {
+        kubernetes {
+            yaml '''
+apiVersion: v1
+kind: Pod
+spec:
+  containers:
+  - name: shell
+    image: ubuntu
+    command:
+    - oops
+    args:
+    - infinity
+'''
+        }
+    }
+    stages {
+        stage('Run') {
+            steps {
+                sh 'hostname'
+            }
+        }
+    }
+}

src/test/resources/org/csanchez/jenkins/plugins/kubernetes/pipeline/podStatusErrorLogs.groovy

@@ -0,0 +1,28 @@
+//noinspection GrPackage
+pipeline {
+    agent {
+        kubernetes {
+            yaml '''
+apiVersion: v1
+kind: Pod
+spec:
+  containers:
+  - name: shell
+    image: ubuntu
+    command:
+    - sleep
+    args:
+    - infinity
+  nodeSelector:
+    disktype: ssd
+'''
+        }
+    }
+    stages {
+        stage('Run') {
+            steps {
+                sh 'hostname'
+            }
+        }
+    }
+}

src/test/resources/org/csanchez/jenkins/plugins/kubernetes/pipeline/podStatusNoErrorLogs.groovy

@@ -0,0 +1,26 @@
+//noinspection GrPackage
+pipeline {
+    agent {
+        kubernetes {
+            yaml '''
+apiVersion: v1
+kind: Pod
+spec:
+  containers:
+  - name: shell
+    image: ubuntu
+    command:
+    - sleep
+    args:
+    - infinity
+'''
+        }
+    }
+    stages {
+        stage('Run') {
+            steps {
+                sh 'hostname'
+            }
+        }
+    }
+}