Log events in build log during pod provisioning #742

Vlatombe · 2020-03-16T10:31:17Z

This listens to pod events during the agent launch and stream them in the build logs. Streaming stops once the agent is up and running.

Happy case

‘Jenkins’ doesn’t have label ‘pp_20-pm7l0’

Created Pod: kubernetes-plugin-test/pp-20-pm7l0-chmxk-m4pww
[Normal][kubernetes-plugin-test/pp-20-pm7l0-chmxk-m4pww][Scheduled] Successfully assigned kubernetes-plugin-test/pp-20-pm7l0-chmxk-m4pww to docker-desktop
[Normal][kubernetes-plugin-test/pp-20-pm7l0-chmxk-m4pww][Pulled] Container image "jenkins/jnlp-slave:4.0.1-1" already present on machine
[Normal][kubernetes-plugin-test/pp-20-pm7l0-chmxk-m4pww][Created] Created container jnlp
[Normal][kubernetes-plugin-test/pp-20-pm7l0-chmxk-m4pww][Started] Started container jnlp

Agent pp-20-pm7l0-chmxk-m4pww is provisioned from template pp_20-pm7l0-chmxk

Unhappy case

Created Pod: kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Scheduled] Successfully assigned kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8 to docker-desktop

[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Pulling] Pulling image "invalid:image"

[Warning][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Failed] Failed to pull image "invalid:image": rpc error: code = Unknown desc = Error response from daemon: pull access denied for invalid, repository does not exist or may require 'docker login': denied: requested access to the resource is denied
[Warning][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Failed] Error: ErrImagePull
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Pulled] Container image "jenkins/jnlp-slave:4.0.1-1" already present on machine
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Created] Created container jnlp
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Started] Started container jnlp
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Pulled] Container image "maven:3.3.9-jdk-8-alpine" already present on machine
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Created] Created container maven

[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Started] Started container maven
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][BackOff] Back-off pulling image "invalid:image"
[Warning][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Failed] Error: ImagePullBackOff

[Warning][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][Failed] Error: ImagePullBackOff
ERROR: Unable to pull Docker image "invalid:image". Check if image tag name is spelled correctly.
[Normal][kubernetes-plugin-test/wrong-image-10-0x2gp-cqgzf-pdrq8][BackOff] Back-off pulling image "invalid:image"

ERROR: Unable to pull Docker image "invalid:image". Check if image tag name is spelled correctly.

Vlatombe · 2020-03-16T13:21:11Z

Need to gracefully degrade if jenkins sa is not able to watch pod events.

Vlatombe · 2020-03-16T15:16:03Z

Looks like SelfSubjectAccessReview is broken in kubernetes-client. Haven't been able to use it.

src/main/java/io/jenkins/plugins/kubernetes/TaskListenerEventWatcher.java

jglick

One thing that has long bothered me: the build log receives a dump of the YAML of the pod if and when the agent launches successfully, but if the launch fails you have to either enable fine logging or have kubectl access in order to see what pod definition Jenkins had tried to create. Is that still true here; and where does the YAML appear relative to these other messages?

src/main/java/io/jenkins/plugins/kubernetes/TaskListenerEventWatcher.java

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

test-in-k8s.yaml

jglick · 2020-03-16T17:55:53Z

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

            template.getWorkspaceVolume().createVolume(client, pod.getMetadata());
            watcher = new AllContainersRunningPodWatcher(client, pod, runListener);
-            try (Watch _w = client.pods().inNamespace(namespace1).withName(podName).watch(watcher)) {
+            try (Watch w1 = client.pods().inNamespace(namespace).withName(podName).watch(watcher);
+                 Watch w2 = client.events().inNamespace(namespace).withField("involvedObject.name", podName).watch(new TaskListenerEventWatcher(podName, runListener))) {
                watcher.await(template.getSlaveConnectTimeout(), TimeUnit.SECONDS);
            } catch (InvalidDockerImageException e) {


Is this special case still needed? I am not really sure what it was doing to begin with; looks suspicious.

It fails the build if one of the docker images is invalid (#497). Ideally I think it would deserve a rework but it works.

But the build would fail anyway, without this clause; the exception would be thrown up out of launch. Right? And with this PR, you would see the appropriate diagnostics right in the log. But the current code here does more, by canceling some queue items (which seem to be any node blocks associated with this build, which is wrong by the way—should only be canceling the node block associated with this pod). If that is needed in order to prevent the build from hanging, then it is needed in many other error cases too. So this does not add up for me.

No, the launcher would just fail but this wouldn't affect the build so the build would wait forever.

should only be canceling the node block associated with this pod

probably.

I do not think this is anything blocking the current PR but it looks like something to revisit.

@jglick I'm revisiting this, not sure how to find out item should be cancelled exactly.
The only correlation I can make seems to be based on label, since at this point the queue item is not yet assigned to the node. There could be several items waiting for a node if they are inside a parallel block or using a static pod template. So, cancel the first one only?

test-in-k8s.yaml

Vlatombe · 2020-03-17T12:45:54Z

Next build should be ok. https://ci.jenkins.io/job/Plugins/job/kubernetes-plugin/job/PR-742/8/display/redirect shows 3 failures without privilege to watch events, pretty much what I expected.

Vlatombe · 2020-03-17T14:05:07Z

One thing that has long bothered me: the build log receives a dump of the YAML of the pod if and when the agent launches successfully, but if the launch fails you have to either enable fine logging or have kubectl access in order to see what pod definition Jenkins had tried to create. Is that still true here; and where does the YAML appear relative to these other messages?

That part isn't touched by this PR, so the yaml is printed once you have an executor. But when using the podTemplate DSL, it could now be dumped before.

lelandsindttouchnet · 2020-03-17T14:18:36Z

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

+        try {
+            return client.events().inNamespace(namespace).withField("involvedObject.name", podName).watch(new TaskListenerEventWatcher(podName, runListener));
+        } catch (KubernetesClientException e) {
+            LOGGER.log(Level.FINE, e, () -> "Cannot watch events on " + namespace + "/" +podName);


Is is reasonable to ask that this log line be written more readily (less restricted than FINE) and include a note/link to instructions for the required level of access needed to watch pod events?

Yes, this seems like it could be at INFO.

Or printed to the runListener.

jglick

Vlatombe force-pushed

Broke incremental review, so I guess I will need to review from scratch.

jglick · 2020-03-17T14:37:10Z

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

+        try {
+            return client.events().inNamespace(namespace).withField("involvedObject.name", podName).watch(new TaskListenerEventWatcher(podName, runListener));
+        } catch (KubernetesClientException e) {
+            LOGGER.log(Level.FINE, e, () -> "Cannot watch events on " + namespace + "/" +podName);


Yes, this seems like it could be at INFO.

jglick · 2020-03-17T14:40:16Z

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

            template.getWorkspaceVolume().createVolume(client, pod.getMetadata());
            watcher = new AllContainersRunningPodWatcher(client, pod, runListener);
-            try (Watch _w = client.pods().inNamespace(namespace1).withName(podName).watch(watcher)) {
+            try (Watch w1 = client.pods().inNamespace(namespace).withName(podName).watch(watcher);
+                 Watch w2 = client.events().inNamespace(namespace).withField("involvedObject.name", podName).watch(new TaskListenerEventWatcher(podName, runListener))) {
                watcher.await(template.getSlaveConnectTimeout(), TimeUnit.SECONDS);
            } catch (InvalidDockerImageException e) {


But the build would fail anyway, without this clause; the exception would be thrown up out of launch. Right? And with this PR, you would see the appropriate diagnostics right in the log. But the current code here does more, by canceling some queue items (which seem to be any node blocks associated with this build, which is wrong by the way—should only be canceling the node block associated with this pod). If that is needed in order to prevent the build from hanging, then it is needed in many other error cases too. So this does not add up for me.

jglick

Still have some questions but looks good.

jglick · 2020-03-17T14:44:05Z

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

-                watcher.await(template.getSlaveConnectTimeout(), TimeUnit.SECONDS);
+            try (Watch w1 = client.pods().inNamespace(namespace).withName(podName).watch(watcher);
+                 Watch w2 = eventWatch(client, podName, namespace, runListener)) {
+                if (watcher != null) {


How could it be null? You just assigned it via a constructor. Does SpotBugs not reject this?

I guess Spotbugs thinks eventWatch could have a side-effect.

AFAICT the watcher field is only written to in the one place above, so it should be definitely non-null here. You can always

Suggested change

if (watcher != null) {

assert watcher != null;

to make it behave.

jglick · 2020-03-17T14:45:40Z

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

+        try {
+            return client.events().inNamespace(namespace).withField("involvedObject.name", podName).watch(new TaskListenerEventWatcher(podName, runListener));
+        } catch (KubernetesClientException e) {
+            LOGGER.log(Level.FINE, e, () -> "Cannot watch events on " + namespace + "/" +podName);


Or printed to the runListener.

mickaelistria · 2020-04-30T16:43:33Z

Thank you so much!

Log events in build log during pod provisioning

e32022b

Vlatombe added the enhancement Improvements label Mar 16, 2020

Grant watch events

2007d04

jglick self-requested a review March 16, 2020 15:15

kerogers-cloudbees reviewed Mar 16, 2020

View reviewed changes

src/main/java/io/jenkins/plugins/kubernetes/TaskListenerEventWatcher.java Outdated Show resolved Hide resolved

kerogers-cloudbees approved these changes Mar 16, 2020

View reviewed changes

jglick reviewed Mar 16, 2020

View reviewed changes

Fix reviews

a60d030

Vlatombe force-pushed the log-events-during-pod-provisioning branch from 226b97b to a60d030 Compare March 17, 2020 08:42

Vlatombe added 2 commits March 17, 2020 10:00

Degrade gracefully if can't watch events

7e1ca05

Remove watch events - should mostly pass

390bfc0

Vlatombe commented Mar 17, 2020

View reviewed changes

test-in-k8s.yaml Outdated Show resolved Hide resolved

Vlatombe added 3 commits March 17, 2020 10:05

Fix changed line

f466c31

Fix spotbugs

4178648

Un-comment role to pass

e234970

Move class and make package-private

d67bd92

Vlatombe requested a review from jglick March 17, 2020 14:06

lelandsindttouchnet reviewed Mar 17, 2020

View reviewed changes

jglick reviewed Mar 17, 2020

View reviewed changes

jglick approved these changes Mar 17, 2020

View reviewed changes

Vlatombe added 2 commits March 17, 2020 15:49

Log unability to watch events with INFO level

7cf310b

Assert watcher is non-null

fde676c

Vlatombe merged commit 74f261b into jenkinsci:master Mar 18, 2020

Vlatombe deleted the log-events-during-pod-provisioning branch March 18, 2020 09:24

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log events in build log during pod provisioning #742

Log events in build log during pod provisioning #742

Vlatombe commented Mar 16, 2020 •

edited

Vlatombe commented Mar 16, 2020

Vlatombe commented Mar 16, 2020

jglick left a comment

jglick Mar 16, 2020

Vlatombe Mar 17, 2020

jglick Mar 17, 2020

Vlatombe Mar 17, 2020 •

edited

jglick Mar 17, 2020

Vlatombe Apr 24, 2020

jglick Apr 27, 2020

Vlatombe commented Mar 17, 2020 •

edited

Vlatombe commented Mar 17, 2020 •

edited

lelandsindttouchnet Mar 17, 2020

jglick Mar 17, 2020

jglick Mar 17, 2020

jglick left a comment

jglick Mar 17, 2020

jglick Mar 17, 2020

jglick left a comment •

edited

jglick Mar 17, 2020

Vlatombe Mar 17, 2020

jglick Mar 17, 2020

Vlatombe Mar 17, 2020

jglick Mar 17, 2020

mickaelistria commented Apr 30, 2020

Log events in build log during pod provisioning #742

Log events in build log during pod provisioning #742

Conversation

Vlatombe commented Mar 16, 2020 • edited

Vlatombe commented Mar 16, 2020

Vlatombe commented Mar 16, 2020

jglick left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Vlatombe Mar 17, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Vlatombe commented Mar 17, 2020 • edited

Vlatombe commented Mar 17, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jglick left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jglick left a comment • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mickaelistria commented Apr 30, 2020

Vlatombe commented Mar 16, 2020 •

edited

Vlatombe Mar 17, 2020 •

edited

Vlatombe commented Mar 17, 2020 •

edited

Vlatombe commented Mar 17, 2020 •

edited

jglick left a comment •

edited