Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Try to remove items from completed builds even if supposedly already cancelled #259

Merged
merged 4 commits into from
Nov 16, 2022
Merged

Try to remove items from completed builds even if supposedly already cancelled #259

Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
b0aeaca
Try to remove items from completed builds even if supposedly already …
jglick Aug 8, 2022
92bf46b
Merge branch 'master' into stopping
jglick Oct 28, 2022
f72d3ea
Logging an extra warning in cases where this PR is active https://git…
jglick Oct 28, 2022
16915df
Merge branch 'master' into stopping
jglick Nov 16, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 6 additions & 2 deletions src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -441,8 +441,12 @@ public String getCookie() {
if (FlowExecutionList.get().isResumptionComplete()) {
// We only do this if resumption is complete so that we do not load the run and resume its execution in this context in normal scenarios.
Run<?, ?> run = runForDisplay();
if (!stopping && run != null && !run.isLogUpdated()) {
stopping = true;
if (run != null && !run.isLogUpdated()) {
Copy link
Member

@dwnusbaum dwnusbaum Aug 8, 2022 •
edited by jglick
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IDK about this. It was only ever intended to run once after a Jenkins restart (and Damien says that in the current case ci.jenkins.io has not yet restarted), so I am worried that removing the guard may lead to log spam or further confusion in some cases. Maybe instead we could add a call to Timer.execute after

workflow-durable-task-step-plugin/src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java

Line 148 in f256ed3

LOGGER.warning(() -> "failed to cancel " + item + " in response to " + cause);
that attempts to cancel the item (or maybe its task, if we think that would make a difference) again after a delay.

I think it would be harmless to test this new code, but if ci.jenkins.io really has not yet restarted, I would be interested to see if the previous code is enough to cancel the task after a restart or not.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be harmless to test this new code, but if ci.jenkins.io really has not yet restarted, I would be interested to see if the previous code is enough to cancel the task after a restart or not.

Oh I'm sorry, our comments crossed: #259 (comment)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am worried that removing the guard may lead to log spam

I was also concerned about this. But @dduportal said that the script (which mimics what this PR would do) indeed canceled the bogus items successfully.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Even if it is fine in this case, it seems clearer and safer to me to trigger an explicit delayed cancellation when the original cancellation attempt fails rather than have getCauseOfBlockage potentially cancel things more than once. For example, if the Timer thread pool is somewhat congested and the task does not run for more than 5 seconds, I think a second task could be scheduled with the proposed code (not really a big deal).

Either way, at this point it seems that the issue seen on ci.jenkins.io happens while the controller is running rather than being a result of some problem with persisted state after a restart, which I did not know was possible and is distinct from what I was trying to fix when I filed #185. Ideally we would try to reproduce the new issue in a test to have a chance at fixing the underlying cause.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the issue seen on ci.jenkins.io happens while the controller is running rather than being a result of some problem with persisted state after a restart

Yes, that was also my understanding.

trigger an explicit delayed cancellation when the original cancellation attempt fails

My reservation is that we do not understand the cause of the original failure to cancel, so we cannot know whether that would actually work. The idea with this PR is to be a final fallback in case other things failed for unknown reasons, to make sure the queue items do not remain there indefinitely.

try to reproduce the new issue in a test

Yes of course that would be best, but I have no clear notion of what happened. BlockedItem.leave not working? One case appeared to relate to a Dependabot PR being closed, but that does nothing to explain why Queue.cancel would fail.

Not sure what to do at this point other than see how things behave on ci.jenkins.io.

Copy link
Member

@basil basil Aug 8, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I haven't been paying attention too closely but I think I've noticed this on ci.jenkins.io when a PR build is aborted due to a new build starting, i.e.:

  1. A PR build starts, some branches might begin executing right away but others might be queued waiting for an agent to come up
  2. A new commit is made
  3. A new PR build starts
  4. Due to disableConcurrentBuilds(abortPrevious: true) the first PR build is aborted
  5. The zombie queue items from the first build remain

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right, that would be a common trigger for

workflow-durable-task-step-plugin/src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java

Lines 144 to 149 in a62ccc9

task.stopping = true;
if (Queue.getInstance().cancel(item)) {
LOGGER.fine(() -> "canceled " + item);
} else {
LOGGER.warning(() -> "failed to cancel " + item + " in response to " + cause);
}
to be run but the question is why cancel would be returning false (as logs confirm) and the item left in the queue.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My reservation is that we do not understand the cause of the original failure to cancel, so we cannot know whether that would actually work. The idea with this PR is to be a final fallback in case other things failed for unknown reasons, to make sure the queue items do not remain there indefinitely.

Well, we do not really know whether this PR works yet either. As far as we know, the existing code would have fixed the issue when Damien restarted ci.jenkins.io, and we have no way to tell whether the new case is being hit. I think we should at least use a distinct log message for the case where stopping is already true so that we would know for sure when it applies and since "Refusing to build ..." does not really make sense as an explanation in this scenario anyway (more like "Desperately trying to cancel ...").

Maybe we should use both approaches, at least temporarily, with a distinct log message in each case, just to see what happens. Knowing whether an asynchronous cancellation right after the synchronous cancellation in stop works or not could be a useful clue to anyone who ends up trying to track down the root cause in the future.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we do not really know whether this PR works yet either

Not directly, but analogous calls made from /script did work, so we have reason to believe it would have.

As far as we know, the existing code would have fixed the issue when Damien restarted ci.jenkins.io

Yes it probably would have, but we do not want to require admins to restart the server just to clean up items we know are invalid.

use both approaches, at least temporarily, with a distinct log message

Could try that. @dduportal do you believe this issue happens enough that you would be likely to see it again?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

jenkins-infra/helpdesk#3211 (comment)

if (stopping) {
LOGGER.warning(() -> "Refusing to build " + PlaceholderTask.this + " and going to cancel it, even though it was supposedly stopped already, because associated build is complete");
} else {
stopping = true;
}
Timer.get().execute(() -> {
if (Queue.getInstance().cancel(this)) {
LOGGER.warning(() -> "Refusing to build " + PlaceholderTask.this + " and cancelling it because associated build is complete");
Expand Down