Try to fix synchronization in SemaphoreStep

[dwnusbaum]

Even after #235, I saw a test flake because a semaphore step hung forever even though SempahoreStep.success was called. The logs indicate an order of operations that show a bug in the existing synchronization:

  10.238 [id=1884]	INFO	o.j.p.w.t.s.SemaphoreStep$Execution#start: Blocking wait/1
  10.239 [id=1839]	INFO	o.j.p.w.test.steps.SemaphoreStep#success: Planning to unblock wait/1 as success

Here is my hypothesis as to what happened. We have two threads: Thread 1 calls SemaphoreStep.start. Thread 2 calls SemaphoreStep.success. They race for the State monitor. I think that thread 1 acquired the State monitor first and ran this entire block:

workflow-support-plugin/src/test/java/org/jenkinsci/plugins/workflow/test/steps/SemaphoreStep.java

Lines 192 to 200 in 1e84e32

	synchronized (s) {
	if (s.returnValues.containsKey(k)) {
	success = true;
	returnValue = s.returnValues.get(k);
	} else if (s.errors.containsKey(k)) {
	failure = true;
	error = s.errors.get(k);
	}
	}

Thread 2 then acquired the State monitor and ran this block:

workflow-support-plugin/src/test/java/org/jenkinsci/plugins/workflow/test/steps/SemaphoreStep.java

Lines 136 to 143 in 1e84e32

	synchronized (s) {
	if (!s.contexts.containsKey(k)) {
	LOGGER.info(() -> "Planning to unblock " + k + " as failure");
	s.errors.put(k, error);
	return;
	}
	c = getContext(s, k);
	}

At this point, s.contexts does not contain k, so Planning to unblock wait/1 as success gets logged, and the monitor is released, but thread 1 already checked s.returnValues and will never check it again. Thread 1 in the meantime proceeded to this synchronized block and ran it once thread 2 released the monitor:

workflow-support-plugin/src/test/java/org/jenkinsci/plugins/workflow/test/steps/SemaphoreStep.java

Lines 210 to 212 in 1e84e32

	synchronized (s) {
	s.contexts.put(k, c);
	}

At this point though, this does nothing. Thread 2 already ran SemaphoreStep.success, and the context did not exist, so it put a value in State.returnValues. Thread 1 had already checked SemaphoreStep.returnValues though, and will not check it again, so the step just hangs forever and the test times out.

CC @jgreffe

[dwnusbaum]

Just keeping this out of the synchronized block as before.

[dwnusbaum]

This is the fix. Other threads now only ever see State in one of two modes: either contexts does not contain the relevant key, and returnValues and errors should be used and will be checked here, or contexts does contain the key, and the StepContext should be used instead. Previously, there was a case where contexts did not contain the key yet but returnValues and errors had already been checked.

[dwnusbaum]

FWIW I think there may be other pre-existing bugs here. What happens if another thread calls success or failure after the first synchronized block above but before this completes? Those threads will call StepContext.onSuccess/StepContext.onFailure before StepExecution.start has completed, which seems unusual, but maybe it's fine.

[dwnusbaum]

Maybe we should change the overall approach, drop support for the synchronous completion cases, and have the step just poll continuously on a background thread looking for results. It would be slower and less efficient, but it also seems less prone to complex synchronization issues.

[dwnusbaum]

Maybe we should change the overall approach

FWIW, I filed #259 with an example of what that could look like.

[jglick]

Those threads will call StepContext.onSuccess/StepContext.onFailure before StepExecution.start has completed

That would be normal if false is returned. It would be weird if start later returns true, but I do not think it is harmful. TBH I do not recall the logic here in workflow-cps very well. Anyway this seems unlikely in a normal test, because it should call wait and then do some stuff before calling success.

[jglick]

jenkinsci/support-core-plugin#515 (comment) ?

[jglick]

Perhaps it would be easier to reason about if instead of three maps there were just one, with values being a union of Blocked | Success(Object) | Error(Throwable)?

[dwnusbaum]

jenkinsci/support-core-plugin#515 (comment) ?

I saw the issue in a proprietary plugin, but indeed the logs for that test failure look the same:

   9.938 [id=63]	INFO	o.j.p.w.t.s.SemaphoreStep$Execution#start: Blocking wait/1
   9.939 [id=141]	INFO	o.j.p.w.test.steps.SemaphoreStep#success: Planning to unblock wait/1 as success

[jglick]

Sorry, four maps, I forgot about started.

[dwnusbaum]

Perhaps it would be easier to reason about if instead of [four] maps there were just one, with values being a union...

Yes, but this pattern is a bit awkward in Java (at least pre-sealed classes/interfaces and future related improvements). I can file another PR with that approach for comparison.

[dwnusbaum]

See #260.

[jglick]

I have a general preference for something like #260 as a refactoring, but OTOH this is fairly simple and looks like it may solve the practical issues, so you should go ahead and get something tested & released.

[jglick]

Those threads will call StepContext.onSuccess/StepContext.onFailure before StepExecution.start has completed

That would be normal if false is returned. It would be weird if start later returns true, but I do not think it is harmful. TBH I do not recall the logic here in workflow-cps very well. Anyway this seems unlikely in a normal test, because it should call wait and then do some stuff before calling success.

[dwnusbaum]

@jglick From some PCT testing, this PR looks fine, but #260 has a few issues that would need to be addressed (#260 (comment)). I can fix them, but is it ok with you if we just go ahead and merge/release this for now?

[jglick]

Feel free to release this PR if it seems to pass PCT. No need to waste days on this.