Trouble stopping pipeline gracefully

[Mathias Ebbensgaard Jensen]

Hi

I use a self-hosted Windows runner for my pipeline.

One of the steps is a python script that runs a compiler as a subprocess.

If I stop the pipeline during compilation, the runner is unable to clean up, and enters 'UNHEALTHY' state, and requires the runner to be restarted. It explicitly states that cleaning up fails because another process is using a file.

I initially thought it was the subprocess that did not get terminated when the python script did, but inspecting running processes reveals that the python script continues execution after the pipeline has been stopped and the runner has failed to clean up.

My understanding is that all commands run by the runner should be terminated when the pipeline is stopped, before it tries to clean up. So is it because I run the python script in way that doesn't allow the runner to terminate it properly, or can it be that the runner itself has an implementation issue? Or do I have a wrong assumption somewhere?

The runner is run on Windows 11

Step:

- python -W ignore::SyntaxWarning Scripts\DevOps\brHelperLibrary\AsProjectCompile.py -c PPC70 -p "$pwd" -w 0; exit $LASTEXITCODE

The python script runs the compiler with:

subprocess.run()

I can see that the python script continues execution (for a short while, until it finishes compiling presumably) using Powershell: Get-Process -Name python3.12

The process ID doesn't change.

P.S.: I added

; exit $LASTEXITCODE

to the end of the python command, as the pipeline otherwise simply continues on when compilation fails, even though the python script returns non-zero. Isn't it expected behavior for the pipeline to stop if a command does that? It feels odd that I have had to add that. Anyways, it feels like it might be relevant.

Relevant runner output:

[2024-04-12 13:24:34,136] Updating runner state to "ONLINE".
[2024-04-12 13:24:35,001] Appending log line to main log.
[2024-04-12 13:24:46,879] Not uploading caches. (numberOfCaches: 1, resultOrError: COMPLETED)
[2024-04-12 13:24:46,881] Not uploading artifacts. (numberOfArtifacts: 0, resultOrError: COMPLETED)
[2024-04-12 13:24:46,884] Updating step progress to PARSING_TEST_RESULTS.
[2024-04-12 13:24:47,003] Appending log line to main log.
[2024-04-12 13:24:47,253] Test report processing complete.
[2024-04-12 13:24:47,254] Updating step progress to COMPLETING_LOGS.
[2024-04-12 13:24:47,461] Shutting down log uploader.
[2024-04-12 13:24:47,462] Tearing down directories.
[2024-04-12 13:24:49,115] An error occurred whilst tearing down directories.
java.nio.file.FileSystemException: C:\Users\COMPANY\Documents\atlassian-bitbucket-pipelines-runner\bin\..\temp\02979930-2fea-5195-a8a3-6c5746594631\1712920533044\build: Processen kan ikke fÑ adgang til filen, da den bruges af en anden proces (process cannot close file, because it is used by another process)
at java.base/sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:92)
at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:103)
at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:108)
at java.base/sun.nio.fs.WindowsFileSystemProvider.implDelete(WindowsFileSystemProvider.java:273)
at java.base/sun.nio.fs.AbstractFileSystemProvider.delete(AbstractFileSystemProvider.java:104)
at java.base/java.nio.file.Files.delete(Files.java:1152)
at com.atlassian.pipelines.runner.core.directory.windows.WindowsDirectoryImpl$1.postVisitDirectory(WindowsDirectoryImpl.java:92)
at com.atlassian.pipelines.runner.core.directory.windows.WindowsDirectoryImpl$1.postVisitDirectory(WindowsDirectoryImpl.java:73)
at java.base/java.nio.file.Files.walkFileTree(Files.java:2808)
at java.base/java.nio.file.Files.walkFileTree(Files.java:2862)
at com.atlassian.pipelines.runner.core.directory.windows.WindowsDirectoryImpl.delete(WindowsDirectoryImpl.java:71)
at com.atlassian.pipelines.runner.core.runtime.common.NativeTemporaryDirectoryStepRuntimeImpl.lambda$tearDownDirectory$5(NativeTemporaryDirectoryStepRuntimeImpl.java:77)
at io.reactivex.internal.operators.completable.CompletableFromAction.subscribeActual(CompletableFromAction.java:35)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletableMerge$CompletableMergeSubscriber.onNext(CompletableMerge.java:99)
at io.reactivex.internal.operators.completable.CompletableMerge$CompletableMergeSubscriber.onNext(CompletableMerge.java:44)
at brave.context.rxjava2.internal.TraceContextSubscriber.onNext(TraceContextSubscriber.java:50)
at io.reactivex.internal.operators.flowable.FlowableMap$MapSubscriber.onNext(FlowableMap.java:68)
at brave.context.rxjava2.internal.TraceContextSubscriber.onNext(TraceContextSubscriber.java:50)
at io.reactivex.internal.operators.flowable.FlowableFromIterable$IteratorSubscription.fastPath(FlowableFromIterable.java:178)
at io.reactivex.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:122)
at io.reactivex.internal.subscribers.BasicFuseableSubscriber.request(BasicFuseableSubscriber.java:153)
at io.reactivex.internal.operators.completable.CompletableMerge$CompletableMergeSubscriber.onSubscribe(CompletableMerge.java:86)
at brave.context.rxjava2.internal.TraceContextSubscriber.onSubscribe(TraceContextSubscriber.java:44)
at io.reactivex.internal.subscribers.BasicFuseableSubscriber.onSubscribe(BasicFuseableSubscriber.java:67)
at brave.context.rxjava2.internal.TraceContextSubscriber.onSubscribe(TraceContextSubscriber.java:44)
at io.reactivex.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:69)
at io.reactivex.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47)
at io.reactivex.Flowable.subscribe(Flowable.java:14935)
at io.reactivex.Flowable.subscribe(Flowable.java:14882)
at brave.context.rxjava2.internal.TraceContextFlowable.subscribeActual(TraceContextFlowable.java:43)
at io.reactivex.Flowable.subscribe(Flowable.java:14935)
at io.reactivex.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:37)
at io.reactivex.Flowable.subscribe(Flowable.java:14935)
at io.reactivex.Flowable.subscribe(Flowable.java:14882)
at brave.context.rxjava2.internal.TraceContextFlowable.subscribeActual(TraceContextFlowable.java:43)
at io.reactivex.Flowable.subscribe(Flowable.java:14935)
at io.reactivex.Flowable.subscribe(Flowable.java:14882)
at io.reactivex.internal.operators.completable.CompletableMerge.subscribeActual(CompletableMerge.java:41)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletableResumeNext.subscribeActual(CompletableResumeNext.java:41)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.single.SingleDelayWithCompletable.subscribeActual(SingleDelayWithCompletable.java:36)
at io.reactivex.Single.subscribe(Single.java:3666)
at brave.context.rxjava2.internal.TraceContextSingle.subscribeActual(TraceContextSingle.java:39)
at io.reactivex.Single.subscribe(Single.java:3666)
at io.reactivex.internal.operators.single.SingleResumeNext.subscribeActual(SingleResumeNext.java:39)
at io.reactivex.Single.subscribe(Single.java:3666)
at brave.context.rxjava2.internal.TraceContextSingle.subscribeActual(TraceContextSingle.java:39)
at io.reactivex.Single.subscribe(Single.java:3666)
at io.reactivex.internal.operators.single.SingleFlatMap$SingleFlatMapCallback.onSuccess(SingleFlatMap.java:84)
at brave.context.rxjava2.internal.TraceContextSingleObserver.onSuccess(TraceContextSingleObserver.java:56)
at io.reactivex.internal.operators.single.SingleFlatMap$SingleFlatMapCallback$FlatMapSingleObserver.onSuccess(SingleFlatMap.java:111)
at brave.context.rxjava2.internal.TraceContextSingleObserver.onSuccess(TraceContextSingleObserver.java:56)
at io.reactivex.internal.operators.single.SingleResumeNext$ResumeMainSingleObserver.onSuccess(SingleResumeNext.java:65)
at brave.context.rxjava2.internal.TraceContextSingleObserver.onSuccess(TraceContextSingleObserver.java:56)
at io.reactivex.internal.operators.single.SingleResumeNext$ResumeMainSingleObserver.onSuccess(SingleResumeNext.java:65)
at brave.context.rxjava2.internal.TraceContextSingleObserver.onSuccess(TraceContextSingleObserver.java:56)
at io.reactivex.internal.observers.ResumeSingleObserver.onSuccess(ResumeSingleObserver.java:46)
at brave.context.rxjava2.internal.TraceContextSingleObserver.onSuccess(TraceContextSingleObserver.java:56)
at io.reactivex.internal.operators.single.SingleFromCallable.subscribeActual(SingleFromCallable.java:56)
at io.reactivex.Single.subscribe(Single.java:3666)
at brave.context.rxjava2.internal.TraceContextSingle.subscribeActual(TraceContextSingle.java:39)
at io.reactivex.Single.subscribe(Single.java:3666)
at io.reactivex.internal.operators.single.SingleDelayWithCompletable$OtherObserver.onComplete(SingleDelayWithCompletable.java:69)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletableAndThenCompletable$NextObserver.onComplete(CompletableAndThenCompletable.java:99)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletableFromRunnable.subscribeActual(CompletableFromRunnable.java:47)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletableAndThenCompletable$SourceObserver.onComplete(CompletableAndThenCompletable.java:67)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletableAndThenCompletable$NextObserver.onComplete(CompletableAndThenCompletable.java:99)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletableDoFinally$DoFinallyObserver.onComplete(CompletableDoFinally.java:78)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletablePeek$CompletableObserverImplementation.onComplete(CompletablePeek.java:115)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletablePeek$CompletableObserverImplementation.onComplete(CompletablePeek.java:115)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletableMergeIterable$MergeCompletableObserver.onComplete(CompletableMergeIterable.java:132)
at io.reactivex.internal.operators.completable.CompletableMergeIterable.subscribeActual(CompletableMergeIterable.java:94)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletableDoFinally.subscribeActual(CompletableDoFinally.java:43)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at brave.context.rxjava2.internal.TraceContextCompletable.subscribeActual(TraceContextCompletable.java:39)
at io.reactivex.Completable.subscribe(Completable.java:2309)
at io.reactivex.internal.operators.completable.CompletableAndThenCompletable$SourceObserver.onComplete(CompletableAndThenCompletable.java:67)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onComplete(TraceContextCompletableObserver.java:53)
at io.reactivex.internal.operators.completable.CompletableOnErrorComplete$OnError.onError(CompletableOnErrorComplete.java:64)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onError(TraceContextCompletableObserver.java:44)
at io.reactivex.internal.operators.completable.CompletablePeek$CompletableObserverImplementation.onError(CompletablePeek.java:95)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onError(TraceContextCompletableObserver.java:44)
at io.reactivex.internal.operators.completable.CompletablePeek$CompletableObserverImplementation.onError(CompletablePeek.java:95)
at brave.context.rxjava2.internal.TraceContextCompletableObserver.onError(TraceContextCompletableObserver.java:44)
at io.reactivex.internal.operators.completable.CompletableObserveOn$ObserveOnCompletableObserver.run(CompletableObserveOn.java:87)
at brave.propagation.CurrentTraceContext$1CurrentTraceContextRunnable.run(CurrentTraceContext.java:264)
at com.atlassian.pipelines.common.trace.rxjava.CopyMdcSchedulerHandler$CopyMdcRunnableAdapter.run(CopyMdcSchedulerHandler.java:74)
at io.reactivex.Scheduler$DisposeTask.run(Scheduler.java:608)
at brave.propagation.CurrentTraceContext$1CurrentTraceContextRunnable.run(CurrentTraceContext.java:264)
at com.atlassian.pipelines.common.trace.rxjava.CopyMdcSchedulerHandler$CopyMdcRunnableAdapter.run(CopyMdcSchedulerHandler.java:74)
at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)
at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at java.base/java.lang.Thread.run(Thread.java:1570)
[2024-04-12 13:24:49,134] Cancelling timeout
[2024-04-12 13:24:49,151] Updating runner state to "UNHEALTHY".
[2024-04-12 13:24:49,397] Completing step with result Result{status=FAILED, error=Some(Error{key='runner.working-directory-teardown-error', message='An error occurred while attempting to clean the build folder. Check the runner logs and manually clean up the build folder on the host machine to fix this issue.', arguments={}})}.
[2024-04-12 13:24:49,633] Setting runner state to not executing step.
[2024-04-12 13:24:49,634] Waiting for next step.
[2024-04-12 13:24:49,635] Finished executing step. StepId{accountUuid={8b0f48d9-52a2-4dde-b56d-1b467f6fdaeb}, repositoryUuid={af6c9708-43d4-4812-aa84-3293f09294f5}, pipelineUuid={d20e97bc-0a9c-47f7-a844-72cc41d3ee2b}, stepUuid={84798574-6e54-47c1-a5b6-a855e14348e3}}
[2024-04-12 13:24:51,525] Unable to properly clean up processes created during step execution. There is a possibility that orphaned processes have been left running.

[Mathias Ebbensgaard Jensen · Accepted solution]

With help from Mark we tried to investigate the issue, without much luck. It looks like it is an issue specific to the PC that runs the pipeline, as the same setup works as expected on another PC. There must be some environment difference.

I see that v2.1.0 of the runner has since been released, which doesn't seem to fix it.

Since it isn't a very big issue and seems hard to debug, we are leaving it here.

[Mark C]

Hi @Mathias Ebbensgaard Jensen,

Welcome to the community.

Would it be possible for you to confirm if you are using a single Windows runner or multiple Windows runners in your self-hosted machine?

Regards,
Mark C

[Mathias Ebbensgaard Jensen]

Hi @Mark C 

Thank you Mark.

We use only a single runner, and only on one machine.

[Mark C]

Hi @Mathias Ebbensgaard Jensen

Thanks for that information.

In order for us to continue our investigation, I went ahead and created a support ticket for you.

You should be able to receive an email notification about it.

Regards,
Mark C