2016-09-23 10:35:32,829 INFO [DefaultProcessorPoolManager] addProcessorPool(T#DEFAULT)
2016-09-23 10:35:32,832 INFO [TransientScottyEngine] Engine is starting up...
2016-09-23 10:35:32,833 INFO [ClasspathWorkflowRepository] Starting up with wfPackages=[my.workflow.test]
2016-09-23 10:35:32,833 INFO [ClasspathWorkflowRepository] adaptedTargetDir=/tmp/cpwfrepo1474641332833
2016-09-23 10:35:33,356 INFO [ClasspathWorkflowRepository] wfSet.size=2
2016-09-23 10:35:33,356 INFO [ClasspathWorkflowRepository] Analysing classfiles
2016-09-23 10:35:33,357 INFO [ClasspathWorkflowRepository] analysing class my.workflow.test.SignupWorkflow
2016-09-23 10:35:33,367 INFO [ClasspathWorkflowRepository] analysing class my.workflow.test.SignupWorkflowImpl
2016-09-23 10:35:33,373 INFO [AbstractWorkflowRepository] Instrumenting classfiles
2016-09-23 10:35:33,395 INFO [ScottyClassAdapter] Transforming my/workflow/test/SignupWorkflowImpl
2016-09-23 10:35:33,395 DEBUG [ScottyClassAdapter] Transforming my/workflow/test/SignupWorkflowImpl.main()V
2016-09-23 10:35:33,400 DEBUG [BuildStackInfoAdapter] label L800074881
2016-09-23 10:35:33,400 DEBUG [BuildStackInfoAdapter] varInsn: ALOAD 0
2016-09-23 10:35:33,400 DEBUG [BuildStackInfoAdapter] insn H_PUTSTATIC
2016-09-23 10:35:33,401 DEBUG [BuildStackInfoAdapter] typeInsn: ANEWARRAY java/lang/String
2016-09-23 10:35:33,401 DEBUG [BuildStackInfoAdapter] insn DUP
2016-09-23 10:35:33,401 DEBUG [BuildStackInfoAdapter] insn H_PUTFIELD
2016-09-23 10:35:33,401 DEBUG [BuildStackInfoAdapter] ldcInsn test123
2016-09-23 10:35:33,402 DEBUG [BuildStackInfoAdapter] insn AASTORE
2016-09-23 10:35:33,402 DEBUG [BuildStackInfoAdapter] methodInsn INVOKEVIRTUAL my/workflow/test/SignupWorkflowImpl waitForAll ([Ljava/lang/String;)V
2016-09-23 10:35:33,403 DEBUG [BuildStackInfoAdapter] label L2030024264
2016-09-23 10:35:33,403 DEBUG [BuildStackInfoAdapter] varInsn: ALOAD 0
2016-09-23 10:35:33,403 DEBUG [BuildStackInfoAdapter] ldcInsn test123
2016-09-23 10:35:33,403 DEBUG [BuildStackInfoAdapter] methodInsn INVOKEVIRTUAL my/workflow/test/SignupWorkflowImpl getAndRemoveResponse (Ljava/lang/String;)Lorg/copperengine/core/Response;
2016-09-23 10:35:33,403 DEBUG [BuildStackInfoAdapter] varInsn: ASTORE 1
2016-09-23 10:35:33,403 DEBUG [BuildStackInfoAdapter] label L1545105159
2016-09-23 10:35:33,404 DEBUG [BuildStackInfoAdapter] fieldInsn GETSTATIC 'java/lang/System' 'err' 'Ljava/io/PrintStream;'
2016-09-23 10:35:33,404 DEBUG [BuildStackInfoAdapter] typeInsn: NEW java/lang/StringBuilder
2016-09-23 10:35:33,404 DEBUG [BuildStackInfoAdapter] insn DUP
2016-09-23 10:35:33,404 DEBUG [BuildStackInfoAdapter] methodInsn INVOKESPECIAL java/lang/StringBuilder <init> ()V
2016-09-23 10:35:33,405 DEBUG [BuildStackInfoAdapter] ldcInsn Got response
2016-09-23 10:35:33,405 DEBUG [BuildStackInfoAdapter] methodInsn INVOKEVIRTUAL java/lang/StringBuilder append (Ljava/lang/String;)Ljava/lang/StringBuilder;
2016-09-23 10:35:33,405 DEBUG [BuildStackInfoAdapter] varInsn: ALOAD 1
2016-09-23 10:35:33,405 DEBUG [BuildStackInfoAdapter] methodInsn INVOKEVIRTUAL java/lang/StringBuilder append (Ljava/lang/Object;)Ljava/lang/StringBuilder;
2016-09-23 10:35:33,406 DEBUG [BuildStackInfoAdapter] methodInsn INVOKEVIRTUAL java/lang/StringBuilder toString ()Ljava/lang/String;
2016-09-23 10:35:33,406 DEBUG [BuildStackInfoAdapter] methodInsn INVOKEVIRTUAL java/io/PrintStream println (Ljava/lang/String;)V
2016-09-23 10:35:33,406 DEBUG [BuildStackInfoAdapter] label L1210147789
2016-09-23 10:35:33,406 DEBUG [BuildStackInfoAdapter] insn RETURN
2016-09-23 10:35:33,406 DEBUG [BuildStackInfoAdapter] label L136268986
2016-09-23 10:35:33,424 INFO [AbstractWorkflowRepository] CheckClassAdapter.verify succeeded for class my/workflow/test/SignupWorkflowImpl
2016-09-23 10:35:33,424 INFO [AbstractWorkflowRepository] Creating classes
2016-09-23 10:35:33,425 INFO [AbstractWorkflowRepository] my.workflow.test.SignupWorkflowImpl created
2016-09-23 10:35:33,434 INFO [ClasspathWorkflowRepository] Startup finished
2016-09-23 10:35:33,434 INFO [TimeoutManager] started
2016-09-23 10:35:33,434 INFO [DefaultEarlyResponseContainer] started
2016-09-23 10:35:33,435 DEBUG [TimeoutManager] Activated at: 1474641333434
2016-09-23 10:35:33,435 INFO [PriorityProcessorPool] ProcessorPool T#DEFAULT: Starting up
2016-09-23 10:35:33,435 DEBUG [TimeoutManager] There are currently no timeout slots - waiting indefinitely...
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,436 INFO [TransientScottyEngine] Engine is running
2016-09-23 10:35:33,436 INFO [Processor] started
2016-09-23 10:35:33,440 DEBUG [Workflow] Creating new my.workflow.test.SignupWorkflowImpl
2016-09-23 10:35:33,441 INFO [DefaultTicketPoolManager] Mapping workflow class 'my.workflow.test.SignupWorkflowImpl' to ticket pool DEFAULT
2016-09-23 10:35:33,441 DEBUG [TicketPool] Trying to obtain 1 tickets. DEFAULT: 0 of 2000 tickets used
2016-09-23 10:35:33,441 DEBUG [TicketPool] Obtained my tickets! DEFAULT: 1 of 2000 tickets used
2016-09-23 10:35:33,458 DEBUG [TransientScottyEngine] registerCallbacks(Workflow [id=724acad8-6dbc-430a-91fa-e6ea83d84d70, priority=5, processorPoolId=T#DEFAULT], ALL, 0, [test123])
2016-09-23 10:35:43,456 DEBUG [TransientScottyEngine] notify(Response [correlationId=test123, response=OLOLO, exception=null, timeout=false, metaData=null, internalProcessingTimeout=null, earlyResponseHandling=true, responseId=null, sequenceId=null])
2016-09-23 10:35:43,457 INFO [TransientScottyEngine] Engine is shutting down...
2016-09-23 10:35:43,458 DEBUG [TicketPool] Released 1 tickets! (Now DEFAULT: 0 of 2000 tickets used)
2016-09-23 10:35:43,458 INFO [DefaultProcessorPoolManager] Shutting down...
2016-09-23 10:35:43,458 INFO [TimeoutManager] stopped
2016-09-23 10:35:43,458 INFO [PriorityProcessorPool] ProcessorPool T#DEFAULT: Shutting down
2016-09-23 10:35:43,458 INFO [DefaultEarlyResponseContainer] stopped
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#0'...
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#1'...
2016-09-23 10:35:43,458 INFO [Processor] stopped
2016-09-23 10:35:43,458 INFO [Processor] stopped
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#2'...
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#3'...
2016-09-23 10:35:43,458 INFO [Processor] stopped
2016-09-23 10:35:43,458 INFO [Processor] stopped
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#4'...
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#5'...
2016-09-23 10:35:43,458 INFO [Processor] stopped
2016-09-23 10:35:43,458 INFO [Processor] stopped
2016-09-23 10:35:43,458 INFO [Processor] Stopping processor 'T#DEFAULT#6'...
2016-09-23 10:35:43,459 INFO [Processor] Stopping processor 'T#DEFAULT#7'...
2016-09-23 10:35:43,459 INFO [Processor] stopped
2016-09-23 10:35:43,459 INFO [Processor] stopped
2016-09-23 10:35:43,459 INFO [TransientScottyEngine] Engine is stopped
Got response Response [correlationId=test123, response=OLOLO, exception=null, timeout=false, metaData=null, internalProcessingTimeout=null, earlyResponseHandling=true, responseId=null, sequenceId=14746413328180001]
Process finished with exit code 0