Potential deadlock from GraphListenerAdapterToPipelineListener

[Dohbedoh]

Jenkins and plugins versions report

Environment

* core: 2.387.3
* opentelemetry:2.11.0
* workflow-api:1208.v0cc7c6e0da_9e
* workflow-cps:3653.v07ea_433c90b_4
* workflow-job:1289.1291.vb_7c188e7e7df
* workflow-support:839.v35e2736cfd5c

Issue

Jenkins shows a deadlock between open-telemetry GraphListenerAdapterToPipelineListener and the Jenkins initialization thread:

==============
Deadlock Found
==============
"Jenkins initialization thread" id=50 (0x32) state=BLOCKED cpu=95%
    - waiting to lock <0x23e558fe> (a org.jenkinsci.plugins.workflow.cps.CpsFlowExecution)
      owned by "Running CpsFlowExecution[Owner[myfolder/myjob/17:myfolder/myjob #17]]" id=1246 (0x4de)
    at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.isComplete(CpsFlowExecution.java:1277)
    at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.getCurrentExecutions(CpsFlowExecution.java:1019)
    at org.jenkinsci.plugins.workflow.flow.FlowExecutionList$ResumeStepExecutionListener.onResumed(FlowExecutionList.java:267)
    at org.jenkinsci.plugins.workflow.flow.FlowExecutionListener.fireResumed(FlowExecutionListener.java:85)
    at org.jenkinsci.plugins.workflow.job.WorkflowRun.onLoad(WorkflowRun.java:589)
    at hudson.model.RunMap.retrieve(RunMap.java:233)
    at hudson.model.RunMap.retrieve(RunMap.java:61)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.load(AbstractLazyLoadRunMap.java:650)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.load(AbstractLazyLoadRunMap.java:632)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.getByNumber(AbstractLazyLoadRunMap.java:530)
    at hudson.model.RunMap.getById(RunMap.java:213)
    at org.jenkinsci.plugins.workflow.job.WorkflowRun$Owner.run(WorkflowRun.java:965)
    at org.jenkinsci.plugins.workflow.job.WorkflowRun$Owner.get(WorkflowRun.java:977)
    at org.jenkinsci.plugins.workflow.flow.FlowExecutionList$1.computeNext(FlowExecutionList.java:76)
    at org.jenkinsci.plugins.workflow.flow.FlowExecutionList$1.computeNext(FlowExecutionList.java:68)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:146)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:141)
    at org.jenkinsci.plugins.workflow.flow.FlowExecutionList$ItemListenerImpl.onLoaded(FlowExecutionList.java:197)
    at jenkins.model.Jenkins.<init>(Jenkins.java:1040)
    at hudson.model.Hudson.<init>(Hudson.java:86)
    at hudson.model.Hudson.<init>(Hudson.java:82)
    at hudson.WebAppMain$3.run(WebAppMain.java:247)

"Running CpsFlowExecution[Owner[myfolder/myjob/17:myfolder/myjob #17]]" id=1246 (0x4de) state=BLOCKED cpu=57%
    - waiting to lock <0x76460394> (a hudson.model.RunMap)
      owned by "Jenkins initialization thread" id=50 (0x32)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.getByNumber(AbstractLazyLoadRunMap.java:519)
    at jenkins.model.lazy.LazyBuildMixIn.getBuildByNumber(LazyBuildMixIn.java:237)
    at org.jenkinsci.plugins.workflow.job.WorkflowJob.getBuildByNumber(WorkflowJob.java:234)
    at org.jenkinsci.plugins.workflow.job.WorkflowJob.getBuildByNumber(WorkflowJob.java:105)
    at hudson.model.Run.fromExternalizableId(Run.java:2498)
    at org.jenkinsci.plugins.workflow.support.steps.build.DownstreamFailureCause.getDownstreamBuild(DownstreamFailureCause.java:47)
    at org.jenkinsci.plugins.workflow.support.steps.build.DownstreamFailureCause.getShortDescription(DownstreamFailureCause.java:63)
    at io.jenkins.plugins.opentelemetry.job.MonitoringPipelineListener.lambda$endCurrentSpan$11(MonitoringPipelineListener.java:308)
    at io.jenkins.plugins.opentelemetry.job.MonitoringPipelineListener$$Lambda$1490/0x00000008425bd440.apply(Unknown Source)
    at java.base@11.0.19/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
    at java.base@11.0.19/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
    at java.base@11.0.19/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
    at java.base@11.0.19/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
    at java.base@11.0.19/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
    at java.base@11.0.19/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.base@11.0.19/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
    at io.jenkins.plugins.opentelemetry.job.MonitoringPipelineListener.endCurrentSpan(MonitoringPipelineListener.java:308)
    at io.jenkins.plugins.opentelemetry.job.MonitoringPipelineListener.onEndParallelStepBranch(MonitoringPipelineListener.java:291)
    at io.jenkins.plugins.opentelemetry.job.jenkins.GraphListenerAdapterToPipelineListener.fireOnAfterEndParallelStepBranch(GraphListenerAdapterToPipelineListener.java:129)
    at io.jenkins.plugins.opentelemetry.job.jenkins.GraphListenerAdapterToPipelineListener.onNewHead(GraphListenerAdapterToPipelineListener.java:64)
    at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1588)
    at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.notifyNewHead(CpsThreadGroup.java:492)
    at org.jenkinsci.plugins.workflow.cps.FlowHead.setNewHead(FlowHead.java:158)
    at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.onProgramEnd(CpsFlowExecution.java:1297)
    at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.croak(CpsFlowExecution.java:882)
    at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService.reportProblem(CpsVmExecutorService.java:57)
    at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$2.call(CpsVmExecutorService.java:69)
    at java.base@11.0.19/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:139)
    at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
    at jenkins.security.ImpersonatingExecutorService$1.run(ImpersonatingExecutorService.java:68)
    at jenkins.util.ErrorLoggingExecutorService.lambda$wrap$0(ErrorLoggingExecutorService.java:51)
    at jenkins.util.ErrorLoggingExecutorService$$Lambda$1086/0x0000000841d64840.run(Unknown Source)
    at java.base@11.0.19/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base@11.0.19/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base@11.0.19/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base@11.0.19/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.19/java.lang.Thread.run(Thread.java:829)

Could be due to the usage of a synchronous GraphListener:

• https://github.com/jenkinsci/opentelemetry-plugin/blob/opentelemetry-2.11.0/src/main/java/io/jenkins/plugins/opentelemetry/job/jenkins/GraphListenerAdapterToPipelineListener.java
• https://github.com/jenkinsci/workflow-api-plugin/blob/1208.v0cc7c6e0da_9e/src/main/java/org/jenkinsci/plugins/workflow/flow/GraphListener.java#L48

What Operating System are you using (both controller, and any agents involved in the problem)?

• JVM Implementation

  • Name: OpenJDK 64-Bit Server VM
  • Vendor: Red Hat, Inc.
  • Version: 11.0.19+7-LTS

• Operating system

  • Name: Linux
  • Architecture: amd64
  • Version: 3.10.0-1160.92.1.el7.x86_64

Reproduction steps

No consistently reproducible. But basically:

• launch many many resumable pipelines
• restart Jenkins

Expected Results

No deadlocks

Actual Results

deadlock

Anything else?

No response

[jglick]

Did you mean to show a thread dump excerpt here?

[dwnusbaum]

@jglick it's in the "Issue" <details> in the description.

[Dohbedoh]

Sorry about that. I tried to follow the issue template of the project. I can make it more visible.

[cyrille-leclerc]

@Dohbedoh @dwnusbaum do you have recommendations on how we can fix this? I looked at the logic of the code and it sounded reasonable to me.

[dwnusbaum]

@cyrille-leclerc GraphListenerAdapterToPipelineListener should probably not extend GraphListener.Synchronous, just GraphListener, see https://github.com/jenkinsci/workflow-api-plugin/blob/ca5fddb3fcebcc6acf823c80600ec7ab9deb0d05/src/main/java/org/jenkinsci/plugins/workflow/flow/GraphListener.java#L48. Or perhaps you could modify it to only perform a small subset of the current logic synchronously if necessary and then offload all of the complex behavior that acquires locks to a separate thread.

[cyrille-leclerc]

Thanks @dwnusbaum .
Some of it definitively needs to be synchronous so that we can associate a span with the FlowNode. I'll brainstorm to see if something can be made async and how we would orchestrate the sync and async parts.

[dwnusbaum]

I think jenkinsci/workflow-cps-plugin#944 fixed the deadlock in the description of this issue, because CpsFlowExecution.notifyListeners will no longer ever run synchronously as a result of CpsFlowExecution.croak, even for instances of GraphListener.Synchronous. I am still investigating to understand whether synchronous notifications from CpsThreadGroup could cause similar problems. I am also checking to see in what cases OTel context propagation might not be working as desired after the fix or if there are any other obvious problems as a result of the asynchronicity for the croak case. Perhaps adding io.opentelemetry.context.Context.taskWrapping to a few ExecutorServices could be enough to preserve the context, but I am not sure.

[dwnusbaum]

I think part of the issue is just that DownstreamFailureCause.getShortDescription and .print try to load the downstream build to get various metadata, which may acquire a lock. Looking at other causes, this seems pretty unusually expensive. Compare with Cause.UpstreamCause, which stores String Job.getFullName, int Run.getNumber, and String Job.getUrl, and then uses those values in getShortDescription and print. I think we might want to use the same approach in DownstreamFailureCause (we'd also need to store Run.getResult()) so that those methods will never actually load the downstream build.

[dwnusbaum]

I tried to see if we could make GraphListenerAdapterToPipelineListener not GraphListener.Synchronous, but the main issue seems to be that async GraphListeners are typically notified of FlowNodes near the end of the build after the build has already completed (e.g. after RunListener.onCompleted/RunListener.onFinalized). For this plugin's listener, it means that the OTel span for the build has already been closed by the time the listener observes the end node for some steps, which breaks the tree structure for the spans and causes some info to be lost.

I don't really see any natural fix for this upstream. Perhaps workflow-cps and/or workflow-job could be adjusted to block build completion until all GraphListener notifications for the build have been processed, but that seems quite awkward.

As far as changing this plugin, maybe we could change things to only start and end the spans synchronously, but add all of the complex attributes asynchronously? Not sure if that is actually possible with the OTel SDK; I'll try to investigate. Alternatively, perhaps we could process RunListener.onCompleted and onFinalized in MonitoringRunListener in this plugin asynchronously using Timer.get() to try to give the GraphListener more time? IDK if this would be consistent though. I'll experiment with it.

And just for the record, even though jenkinsci/workflow-cps-plugin#944 fixed the reported error, I think DownstreamFailureCause could still cause problems in other contexts, but it may be less likely. We could make some straightforward changes to improve that class though as described above. However, even if we did that, I am still concerned about the Git related StepHandler classes here, which run in the context of the synchronous GraphListener, and particularly AbstractGitStepHandler.searchGitUserName which performs a credentials lookup in this context.

[jglick]

Did not follow most of this discussion but

block build completion until all GraphListener notifications for the build have been processed

sounds reasonable enough.

[dwnusbaum]

Swapping the order of local listeners vs listeners from extensions in CpsFlowExecution.getListenersToRun so that WorkflowRun$GraphL runs last instead of first actually fixes most of the problems with switching to an async GraphListener here. That seems like a potentially reasonable change. I forgot that GraphL is already async.

A few tests related to synchronous steps still fail though (the ones added in #896). The problem is that synchronous steps execute before the async GraphListener observes the FlowNode for the step, and so the span for the step execution is not associated with the expected parent span. I'll see if we can do anything about this case.

[dwnusbaum]

Supporting context propagation for synchronous steps while preserving the expected span hierarchy looks like a more fundamental problem. We need to create the span for the step (done by the GraphListener) before the span for its execution (done by the StepExecution). We can't change the timing of the execution itself, so we are basically forced to create the step spans synchronously.

Given that, I tried to see if there was a way to add attributes to spans after they have been created, so that we could keep the main listener logic synchronous and refactor just the concerning stuff like the credentials lookup in AbstractGitStepHandler.searchGitUserName to run asynchronously. It turns out that you can call Span.setAttribute asynchronously after the Span has started, but if the Span has ended, it does nothing (as far as I can tell). In practice here I think it means that we have the duration of the git checkout to perform the credentials lookup and have the async task complete for the attribute to get added. In practice this will probably work out since the git step has to perform the same credentials lookup, but this feels pretty messy.

So, here's my summary:

1. I think the deadlock in the ticket description is no longer possible due to Avoid holding locks from croak when calling notifyListeners workflow-cps-plugin#944.
2. I think we should consider adjusting DownstreamFailureCause to not actually load the downstream build in getShortDescription and print, which would also have prevented the deadlock.
   • See Avoid loading the downstream build in DownstreamFailureCause.getShortDescription and .print pipeline-build-step-plugin#161
3. I do not see a way to make GraphListenerAdapterToPipelineListener asynchronous without breaking the expected span hierarchies for synchronous step executions that emit OTel spans (i.e. breaking all of Add trace context propagation in atomic steps #896), at least not without substantial changes to this plugin.
4. I think we should consider adjusting listener notification order in CpsFlowExecution so that WorkflowRun$GraphL runs after all other listeners, or at least the part that calls WorkflowRun.finish when it sees FlowEndNode should run last. I will investigate this a bit more and file at least a draft PR showing the idea, even though it doesn't seem to be enough for this plugin.
   • Notify GraphListener extensions prior to listeners added via FlowExecution.addListener workflow-cps-plugin#1052 shows this idea. Doing this in a way that does not break other existing listeners would take some new effort, so I am probably just going to set this aside in case in comes up again in the future.
5. The primary concern I have with GraphListenerAdapterToPipelineListener remaining GraphListener.Synchronous is with the credentials lookup in AbstractGitStepHandler.searchGitUserName, since in the worst case, credentials lookups can involve multiple network calls. Apart from that, I think everything running synchronously seems more or less ok. @cyrille-leclerc what do you think about my second paragraph in this comment (this one), essentially keeping things mostly as-is but doing the credentials lookup for ExtendedJenkinsAttributes.GIT_USERNAME asynchronously and adding to to the Span after it has already started rather than adding the attribute to the SpanBuilder? This seems to work ok in basic testing but I have a very limited understanding of the OTel SDK. I can file a PR here to make this change if you think it makes sense.