5

We have a Tridion 9 deployer (receiver and worker) with some custom code that is having occasional failures in the Deploying phase.

enter image description here

The failures are random and after some persistent republishing, the components do actually get published successfully. For example, I publish 100 components, 20 fails, then I republish those 20, 5 fails, etc...

All of these components have in common are assets (thumbnails).

These are the logs that I have extracted by setting the deployer worker to DEBUG and grepping the transaction ID as well as the thread that was processing the request.

2019-11-20 13:34:08,728 DEBUG [pool(JMSDeploymentQueue - myapp-qa-ContentQueue)-1-thread-1] JSONCommandSerializer - Command de-serialized 'JSONCommand{verbs=[Content], action='TridionBootstrap', binaryIds=[tcm_0-1693950-66560.Content.zip], ex ecutionId='tcm:0-1693950-66560', properties={}}'
 2019-11-20 13:34:09,649 INFO  [pool-3-thread-1] CommandQueuePoller - Current active: 7 max: 11 scheduling: JSONCommand{verbs=[Content], action='TridionBootstrap', binaryIds=[tcm_0-1693950-66560.Content.zip], executionId='tcm:0-1693950-66560 ', properties={}}
 2019-11-20 13:34:09,649 INFO  [pool(Queue Workers - myapp-qa-ContentQueue)-4-thread-11] CommandQueuePoller - Processing command: JSONCommand{verbs=[Content], action='TridionBootstrap', binaryIds=[tcm_0-1693950-66560.Content.zip], executionId ='tcm:0-1693950-66560', properties={}}
 2019-11-20 13:34:09,649 DEBUG [pool(Queue Workers - capi-qa-ContentQueue)-4-thread-11] AkkaProcessingService - Handling request: JSONCommand{verbs=[Content], action='TridionBootstrap', binaryIds=[tcm_0-1693950-66560.Content.zip], executionI d='tcm:0-1693950-66560', properties={}}
 2019-11-20 13:34:09,649 DEBUG [pool(Queue Workers - myapp-qa-ContentQueue)-4-thread-11] BasicProcessingContextProvider - Creating initial processing context for command: JSONCommand{verbs=[Content], action='TridionBootstrap', binaryIds=[tcm_ 0-1693950-66560.Content.zip], executionId='tcm:0-1693950-66560', properties={}}
 2019-11-20 13:34:09,649 DEBUG [pool(Queue Workers - myapp-qa-ContentQueue)-4-thread-11] BasicProcessingContextProvider - Created: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action =  TridionBootstrap verbs = [Content], currentPipeline = Optional[BasicPipeline [id=Tridion-Bootstrap, finalizePipeline=false, actions=[TridionBootstrap], verb=[Commit, Content, Prepare, Rollback]]], currentStep = Optional[BasicStep [id=Tridi onUnzipStep, factory=]]], finalizeContext = false]
 2019-11-20 13:34:09,651 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] ExecutionActor - Started deployment for execution 'tcm:0-1693950-66560'
 2019-11-20 13:34:09,653 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new execution entity for execution id: tcm:0-1693950-66560
 2019-11-20 13:34:09,661 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] PipelineActor - Start pipeline 'Tridion-Bootstrap' for 'tcm:0-1693950-66560'.
 2019-11-20 13:34:09,665 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new pipeline entity for execution id: tcm:0-1693950-66560 and pipeline id: Tridion-Bootstrap
 2019-11-20 13:34:09,676 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Start step 'Optional[BasicStep [id=TridionUnzipStep, factory=]]' for 'tcm:0-1693950-66560'
 2019-11-20 13:34:09,678 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Bootstrap and step id: TridionUnzipStep
 2019-11-20 13:34:09,735 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and key = InWait
 2019-11-20 13:34:09,735 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and keys = [InWait]
 2019-11-20 13:34:09,737 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Found 0 step data in session database for ExecutionId = tcm:0-1693950-66560 and keys = [InWait]
 2019-11-20 13:34:09,763 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - (metric) type=stepExecutionTime executionIdVal=tcm:0-1693950-66560 pipelineIdVal=Tridion-Bootstrap stepIdVal=TridionUnzipStep elapsed =67
 2019-11-20 13:34:09,765 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Found step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Bootstrap and step id: TridionUnzipStep
 2019-11-20 13:34:09,775 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Received processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950 -66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Bootstrap, finalizePipeline=false, actions=[TridionBootstrap], verb=[Commit, Content, Prepare, Rollback] ]], currentStep = Optional[BasicStep [id=TridionUnzipStep, factory=]]], finalizeContext = false]. Proceeding to create new processing context.
 2019-11-20 13:34:09,775 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Created new processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693 950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Bootstrap, finalizePipeline=false, actions=[TridionBootstrap], verb=[Commit, Content, Prepare, Rollba ck]]], currentStep = Optional.empty], finalizeContext = false]
 2019-11-20 13:34:09,775 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] PipelineActor - Step 'TridionUnzipStep' of pipelineId: 'Tridion-Bootstrap' for 'tcm:0-1693950-66560' processed.
 2019-11-20 13:34:09,777 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Found pipeline entity for execution id: tcm:0-1693950-66560 and pipeline id: Tridion-Bootstrap
 2019-11-20 13:34:09,787 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] ExecutionActor - Processed pipeline 'Optional[BasicPipeline [id=Tridion-Bootstrap, finalizePipeline=false, actions=[TridionBootstrap], verb=[Comm it, Content, Prepare, Rollback]]]' for execution tcm:0-1693950-66560
 2019-11-20 13:34:09,787 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Received processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950 -66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Bootstrap, finalizePipeline=false, actions=[TridionBootstrap], verb=[Commit, Content, Prepare, Rollback] ]], currentStep = Optional.empty], finalizeContext = false]. Proceeding to create new processing context.
 2019-11-20 13:34:09,787 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Created new processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693 950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]]], currentStep = Optional[Ba sicStep [id=BinaryDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]], finalizeContext = false]
 2019-11-20 13:34:09,788 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] PipelineActor - Start pipeline 'Tridion-Process-Deploy' for 'tcm:0-1693950-66560'.
 2019-11-20 13:34:09,790 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new pipeline entity for execution id: tcm:0-1693950-66560 and pipeline id: Tridion-Process-Deploy
 2019-11-20 13:34:09,803 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Start step 'Optional[BasicStep [id=BinaryDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]' for 'tcm:0-1 693950-66560'
 2019-11-20 13:34:09,805 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Process-Deploy and step id: BinaryDeploy
 2019-11-20 13:34:09,815 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] TridionDeployerStepAdapter - Creating new transaction log for execution id: tcm:0-1693950-66560 and step id: BinaryDeploy
 2019-11-20 13:34:09,818 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and key = InWait
2019-11-20 13:34:09,818 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and keys = [InWait]
2019-11-20 13:34:09,820 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Found 0 step data in session database for ExecutionId = tcm:0-1693950-66560 and keys = [InWait]
2019-11-20 13:34:09,825 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and key = UnzipLocation
2019-11-20 13:34:09,825 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and keys = [UnzipLocation]
2019-11-20 13:34:09,827 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Found 1 step data in session database for ExecutionId = tcm:0-1693950-66560 and keys = [UnzipLocation]
2019-11-20 13:34:09,854 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binaries processing is started
2019-11-20 13:34:09,876 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binary item processing is started. Path: /esES/Images/2019/09/test-stan-smtih_193-147195.png
2019-11-20 13:34:11,235 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binary item processing is completed. Path: /esES/Images/2019/09/test-stan-smtih_193-147195.png
2019-11-20 13:34:11,240 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binary item processing is started. Path: /esES/Images/2019/09/test-gazelle_193-147196.jpg
2019-11-20 13:34:12,186 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binary item processing is completed. Path: /esES/Images/2019/09/test-gazelle_193-147196.jpg
2019-11-20 13:34:12,192 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binary item processing is started. Path: /esES/Images/2019/09/test-zx-4000_193-147197.jpeg
2019-11-20 13:34:12,862 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binary item processing is completed. Path: /esES/Images/2019/09/test-zx-4000_193-147197.jpeg
2019-11-20 13:34:12,862 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BinaryDeployHandler - [tcm:0-1693950-66560] Package binaries processing is completed
2019-11-20 13:34:12,872 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - (metric) type=stepExecutionTime executionIdVal=tcm:0-1693950-66560 pipelineIdVal=Tridion-Process-Deploy stepIdVal=BinaryDeploy elapsed=3057
2019-11-20 13:34:12,874 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Found step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Process-Deploy and step id: BinaryDeploy
2019-11-20 13:34:12,881 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Received processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]]], currentStep = Optional[BasicStep [id=BinaryDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]], finalizeContext = false]. Proceeding to create new processing context.
2019-11-20 13:34:12,882 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Created new processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]]], currentStep = Optional[BasicStep [id=ComponentDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]], finalizeContext = false]
2019-11-20 13:34:12,882 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] PipelineActor - Step 'BinaryDeploy' of pipelineId: 'Tridion-Process-Deploy' for 'tcm:0-1693950-66560' processed.
2019-11-20 13:34:12,882 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Start step 'Optional[BasicStep [id=ComponentDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]' for 'tcm:0-1693950-66560'
2019-11-20 13:34:12,884 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Process-Deploy and step id: ComponentDeploy
2019-11-20 13:34:12,892 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] TridionDeployerStepAdapter - Creating new transaction log for execution id: tcm:0-1693950-66560 and step id: ComponentDeploy
2019-11-20 13:34:12,894 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and key = InWait
2019-11-20 13:34:12,894 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and keys = [InWait]
2019-11-20 13:34:12,902 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Found 0 step data in session database for ExecutionId = tcm:0-1693950-66560 and keys = [InWait]
2019-11-20 13:34:12,909 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and key = UnzipLocation
2019-11-20 13:34:12,909 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and keys = [UnzipLocation]
2019-11-20 13:34:12,912 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Found 1 step data in session database for ExecutionId = tcm:0-1693950-66560 and keys = [UnzipLocation]
2019-11-20 13:34:12,927 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] ContentDeployHandler - [tcm:0-1693950-66560] Package content processing is started
2019-11-20 13:34:12,932 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] ContentDeployHandler - [tcm:0-1693950-66560] Package content template: MyApp.Templates.CUSTOM.v2 (tcm:193-116549-32)

2019-11-20 13:34:23,402 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] LocalThreadTransaction - Received a set on the new method with value: null
2019-11-20 13:34:23,402 WARN  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Step 'ComponentDeploy' for 'tcm:0-1693950-66560' failed with message: java.lang.RuntimeException: Timeout waiting for parallel processing
2019-11-20 13:34:23,404 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Found step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Process-Deploy and step id: ComponentDeploy
2019-11-20 13:34:23,412 ERROR [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Step 'ComponentDeploy' for 'tcm:0-1693950-66560' can NOT retry
2019-11-20 13:34:23,412 ERROR [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Step 'ComponentDeploy' for 'tcm:0-1693950-66560':
java.lang.RuntimeException: Timeout waiting for parallel processing.
        at com.cloudinary.strategies.AbstractUploaderStrategy.processResponse(AbstractUploaderStrategy.java:85)
        at com.cloudinary.http44.UploaderStrategy.callApi(UploaderStrategy.java:140)
        at com.cloudinary.Uploader.callApi(Uploader.java:34)
        at com.cloudinary.Uploader.upload(Uploader.java:76)
        at com.cloudinary.Uploader.upload(Uploader.java:68)
        at com.myapp.deployer.modules.client.binary.CloudinaryClient.put(CloudinaryClient.java:95)
        at com.myapp.deployer.modules.client.widget.DefaultWidgetClient.updateUrl(DefaultWidgetClient.java:23)
        at com.myapp.deployer.modules.handlers.content.ContentDeployHandler.parseOrCopyVideoUrls(ContentDeployHandler.java:196)
        at com.myapp.deployer.modules.handlers.content.ContentDeployHandler.handle(ContentDeployHandler.java:97)
        at com.myapp.deployer.modules.MyAppContentDeployModule.process(MyAppContentDeployModule.java:31)
        at com.sdl.delivery.deployer.steps.TridionDeployerStepAdapter.process(TridionDeployerStepAdapter.java:91)
        at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.execute(StepActor.scala:72)
        at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.com$sdl$delivery$deployer$engine$pipeline$actor$StepActor$$processStep(StepActor.scala:57)
        at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor$$anonfun$receive$1.applyOrElse(StepActor.scala:40)
        at akka.actor.Actor.aroundReceive(Actor.scala:517)
        at akka.actor.Actor.aroundReceive$(Actor.scala:515)
        at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.aroundReceive(StepActor.scala:26)
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:588)
        at akka.actor.ActorCell.invoke(ActorCell.scala:557)
        at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:258)
        at akka.dispatch.Mailbox.run(Mailbox.scala:225)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2019-11-20 13:34:23,412 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Received processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]]], currentStep = Optional[BasicStep [id=ComponentDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]], finalizeContext = false]. Proceeding to create finalizing processing context.
2019-11-20 13:34:23,412 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Current pipeline was found. Looking for final pipeline of: BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]].
2019-11-20 13:34:23,412 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicPipelineProvider - Found 6 pipelines after pipeline: Tridion-Process-Deploy. Filtering for finalizing pipeline that matches action Deploy and verbs [Commit, Content, PreCommit, Process].
2019-11-20 13:34:23,412 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Finalize pipeline configured after : BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]] is Optional[BasicPipeline [id=Tridion-Cleanup, finalizePipeline=true, actions=[Undeploy, Deploy], verb=[*]]].
2019-11-20 13:34:23,412 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicProcessingContextProvider - Created finalizing processing context: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Cleanup, finalizePipeline=true, actions=[Undeploy, Deploy], verb=[*]]], currentStep = Optional[BasicStep [id=TridionCleanupStep, factory=]]], finalizeContext = true]
2019-11-20 13:34:23,412 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] PipelineActor - Received FinalizeExecutionException for original 'BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Process-Deploy, finalizePipeline=false, actions=[Deploy], verb=[Process]]], currentStep = Optional[BasicStep [id=ComponentDeploy, factory=com.sdl.delivery.deployer.steps.TridionExecutableStepFactory]]], finalizeContext = false]'. Will try to finalize execution with finalizeProcessingContext: BasicProcessingContext [executionId = tcm:0-1693950-66560, binaryId = tcm_0-1693950-66560.Content.zip, action = Deploy verbs = [Commit, Content, PreCommit, Process], currentPipeline = Optional[BasicPipeline [id=Tridion-Cleanup, finalizePipeline=true, actions=[Undeploy, Deploy], verb=[*]]], currentStep = Optional[BasicStep [id=TridionCleanupStep, factory=]]], finalizeContext = true]
2019-11-20 13:34:23,414 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Found pipeline entity for execution id: tcm:0-1693950-66560 and pipeline id: Tridion-Process-Deploy
2019-11-20 13:34:23,420 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] PipelineActor - Start finalizing pipeline 'Tridion-Cleanup' for 'tcm:0-1693950-66560'.
2019-11-20 13:34:23,422 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new pipeline entity for execution id: tcm:0-1693950-66560 and pipeline id: Tridion-Cleanup
2019-11-20 13:34:23,431 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] StepActor - Start step 'Optional[BasicStep [id=TridionCleanupStep, factory=]]' of finalizing pipeline for 'tcm:0-1693950-66560'
2019-11-20 13:34:23,433 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStateStore - Creating new step entity for execution id: tcm:0-1693950-66560, pipeline id: Tridion-Cleanup and step id: TridionCleanupStep
2019-11-20 13:34:23,439 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicExecutableStepFactoryManager - Providing ExecutableStep for PipelineId: Tridion-Cleanup and StepId: TridionCleanupStep
2019-11-20 13:34:23,439 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] BasicExecutableStepFactoryManager - Factory for stepId: TridionCleanupStep not defined. Using SpringAwareExecutableStepFactory
2019-11-20 13:34:23,439 INFO  [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] SpringAwareExecutableStepFactory - Initialized executable step TridionCleanupStep using SpringAwareExecutableStepFactory factory
2019-11-20 13:34:23,452 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and key = ZipLocation
2019-11-20 13:34:23,452 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Trying to find all step data for ExecutionId = tcm:0-1693950-66560 and keys = [ZipLocation]
2019-11-20 13:34:23,457 DEBUG [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1757] HybridStepDataStore - Found 1 step data in session database for ExecutionId = tcm:0-1693950-66560 and keys = [ZipLocation]

See the full debug log here, it was to big to paste here -> https://we.tl/t-mZvWgXe1rJ

I am by no means an expert in Tridion but does this seems like there is a limitation in our custom code processing? We are integrated with a 3rd party API for uploading assets (Cloudinary) so not sure if this is the root cause when we publish a lot of components.

Any help is appreciated. Thanks

  • Welcome to Triidion Stackexchange, error message indeed, when trying to call cloudinary.Uploader.upload API it's getting a timeout – Velmurugan Nov 20 '19 at 21:07
  • you might need to increase the timeout value, this might be useful refer to this article support.cloudinary.com/hc/en-us/articles/… – Velmurugan Nov 20 '19 at 21:11
  • 1
    whats up uros :D – Marko Milic Nov 20 '19 at 21:47
3

Uros, this is Cloudinary issue as seen in Stack trace:

at com.cloudinary.strategies.AbstractUploaderStrategy.processResponse(AbstractUploaderStrategy.java:85)
        at com.cloudinary.http44.UploaderStrategy.callApi(UploaderStrategy.java:140)
        at com.cloudinary.Uploader.callApi(Uploader.java:34)
        at com.cloudinary.Uploader.upload(Uploader.java:76)
        at com.cloudinary.Uploader.upload(Uploader.java:68)

So I guess we should take a look in cloudinary. Maybe it is being hit too much by PUT requests when we have mass publishing. What I suggest is that we have performance testing over Cloudinary to see how many requests it can handle. We can also implement a retry mechanism in ContentDeployHandler to try few times to deploy the image to Cloudinary. If it fails on n-th time, we can propagate the exception to deployer worker and have a failed transactions.

| improve this answer | |
  • Thanks, we were being rate-limited by Cloudinary, that's where the error was coming from :) – Urosh T. Nov 27 '19 at 15:22
  • Cool. Its probably because cloudinary was being hit by multiple deployer treads all at once. Especially in cases when you publish in all child publications. Then all transactions hit same asset all at once – Marko Milic Nov 27 '19 at 15:26

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.