Drone-runner-kube 1.0.0-beta.12 - Failed step blocks pipeline

marko-gacesa · September 16, 2021, 11:34am

Hi, @mknapcok. Thanks for sharing this.

In the runner’s log, I found that the step “check-dependencies” (container=drone-3e4r5l615rtj4qstaa6x) was never finished. It was launched at “2021-09-15T21:03:05Z”, successfully started two seconds later, but a Kubernetes event for the step termination never arrived. From the screenshot I can see the step was still running at “2021-09-15T21:14:25Z” when the pod was deleted (after you canceled the build).

What was the step doing? Is it possible that the step itself got stuck, and not the runner, because the log looks normal. Remember, there’s no timeout for execution of steps.

Also, it’s weird that the first time the runner failed to delete a pod. What version of Kubernetes are you using?

mknapcok · September 19, 2021, 7:59pm

Sorry, now I see I blacked out all lines, it was finished with Error 1, this step is meant to fail, it’s just to display indirect dependecies for our devs. The expected behaviour is to fail and continue with next step.

With the beta.12 it stays stuck indefinitely in this state.

mknapcok · September 19, 2021, 8:18pm

As I was reproducing this issue now, the logs don’t reveal anything obvious. Here’s a snippet from logs regarding container=drone-c86no4qtxiixqe22hep0

time="2021-09-19T20:06:15Z" level=debug msg="Engine: Starting step" build.id=4359 build.number=2175 container=drone-c86no4qtxiixqe22hep0 image="698591829921.dkr.ecr.eu-central-1.amazonaws.com/base-php:1.6" namespace=drone placeholder="drone/placeholder:1" pod=drone-4dgyh7gom0u4zfr8yyf7 repo.id=6 repo.name=smartlook-application repo.namespace=smartlook stage.id=45862 stage.name=checks stage.number=1 step=check-dependencies step.name=check-dependencies thread=11
time="2021-09-19T20:06:16Z" level=debug msg="Launched containers. Duration=0.10s" count=1 failed=0 success=1
time="2021-09-19T20:06:16Z" level=debug msg="PodWatcher: Waiting..." container=drone-c86no4qtxiixqe22hep0 pod=drone-4dgyh7gom0u4zfr8yyf7 stepState=running
time="2021-09-19T20:06:16Z" level=trace msg="PodWatcher: Event" event=MODIFIED pod=drone-4dgyh7gom0u4zfr8yyf7
time="2021-09-19T20:06:16Z" level=trace msg="PodWatcher: Event" event=MODIFIED pod=drone-4dgyh7gom0u4zfr8yyf7
time="2021-09-19T20:06:17Z" level=trace msg="PodWatcher: Event" event=MODIFIED pod=drone-4dgyh7gom0u4zfr8yyf7
time="2021-09-19T20:06:17Z" level=debug msg="PodWatcher: Container state changed" container=drone-c86no4qtxiixqe22hep0 image="698591829921.dkr.ecr.eu-central-1.amazonaws.com/base-php:1.6" pod=drone-4dgyh7gom0u4zfr8yyf7 restartCount=1 state=RUNNING stepState=running
time="2021-09-19T20:06:17Z" level=debug msg="PodWatcher: Wait finished. Duration=0.98s" container=drone-c86no4qtxiixqe22hep0 error="<nil>" pod=drone-4dgyh7gom0u4zfr8yyf7 stepState=running
time="2021-09-19T20:06:22Z" level=trace msg="PodWatcher: Event" event=MODIFIED pod=drone-4dgyh7gom0u4zfr8yyf7
time="2021-09-19T20:06:22Z" level=debug msg="PodWatcher: Waiting..." container=drone-c86no4qtxiixqe22hep0 pod=drone-4dgyh7gom0u4zfr8yyf7 stepState=finished
time="2021-09-19T20:06:23Z" level=trace msg="PodWatcher: Periodic container state check" namespace=drone pod=drone-cqc2oqqunfu0gv4gxcsp
time="2021-09-19T20:06:23Z" level=trace msg="PodWatcher: Periodic container state check" namespace=drone pod=drone-itxh4eebvuucmkp3nsh7
time="2021-09-19T20:06:23Z" level=trace msg="PodWatcher: Periodic container state check" namespace=drone pod=drone-yb4foy9uqoo3kg9ieg60
time="2021-09-19T20:06:25Z" level=trace msg="PodWatcher: Periodic container state check" namespace=drone pod=drone-4dgyh7gom0u4zfr8yyf7

After manually cancelling at 20:06 the build, the pod kept running. There are still coming logs with checking state.

If you want to see this bug personally I’m happy to get on a call with you and show you.

marko-gacesa · September 21, 2021, 9:19am

Ok, before we get on a call can you please provide these things:

Your Kubernetes version?
“kubectl describe pod” output of the problematic pod

Thanks!

mknapcok · September 21, 2021, 9:37am

Yeah, sure I will. Kubernetes version is 1.21 and describe pod will be in next post.
Here I have another case of a step failing but staying running:

mknapcok · September 21, 2021, 9:45am

Here’s describe pod with failed step “check-dependecies”

mknapcok · September 21, 2021, 9:48am

Here’s the one from pod with failed “test” step that keeps running:

marko-gacesa · September 21, 2021, 3:18pm

@mknapcok, please try out the latest image. It should solve your problem.

mknapcok · September 21, 2021, 6:19pm

Yeah, it seems it helped with the build that was getting stuck

I’ll let it run tomorrow and see if more builds will be done like this.

mknapcok · September 23, 2021, 9:52am

Okay, it look’s like the steps that finish with error fail successfuly.
Although we discovered a different bug now with step that fails but in the end, in Drone UI it displays this error message:

During the run, the logs are normally displayed as usual but as the run is finished it’s displaying this messsage.
I was monitoring logs in a container on k8s during the run of the build and the logs finish with this lines:

We’d expect this lines will be displayed in Drone server UI but unfortunately we just find error message shown on a picture above.

Note: Pod ID’s don’t match as the screenshot with logs was made on pod, that was triggered with kube-runner beta.12 as I was testing previous behavior. Anyway the logs were the same on the pod, that produced the error on first picture. This behavior is happening with drone-runner-kube:latest.

mknapcok · September 23, 2021, 10:06am

This was run with drone-runner-kube:1.0.0-beta.9 and I’d say this is the expected behavior:

mknapcok · September 23, 2021, 11:19am

Yeah, and the same happens with the build I was showing in the beginning. Build fails but doesn’t display logs.

bradrydzewski · September 23, 2021, 12:54pm

Failing to display the logs could be an issue with the user interface as opposed to an issue with the runner. Can you see the logs if you manually try to access the log endpoint in your browser? The log endpoint follows this pattern:

/api/repos/{organization}/{repo}/builds/{buildNumber}/logs/{stageNumber}/{stepNumber}

cc @d1wilko

mknapcok · September 23, 2021, 2:13pm

Yes, I am able to access them this way:

bradrydzewski · September 23, 2021, 3:27pm

Thanks for confirming. There is a UI issue where we were not displaying logs correctly when an error exists. I thought we fixed this in a recent release, but we can verify.

mknapcok · September 23, 2021, 3:59pm

I updated Drone Server to 2.4.0 but this still happened.

And I was able to get to the logs endpoint in browser.

d1wilko · September 27, 2021, 1:52pm

Ok I’ve added back in the console logs when an error is thrown with this PR - show error and console logs for buld steps by d1wilko · Pull Request #387 · drone/drone-ui · GitHub

it should be in the next drone release

mknapcok · September 30, 2021, 1:09pm

When will this be released please?
I’m waiting for release everyday now

d1wilko · October 1, 2021, 9:24am

Hey @mknapcok theres a few other fixes we are working to get out which we would like to bundle into a single release.

I would say we will do a release at the tail end of next week - thanks

mknapcok · October 12, 2021, 1:37pm

Hi @d1wilko,
how’s the release going?
It’s pain reading the logs only from the api