Fix workflow manager concurrency #97

jbornemann · 2016-01-12T00:05:08Z

jbornemann · 2016-01-12T00:05:46Z

while [ $? -ne 1 ]; do
    ./gradlew test --tests *WorkflowManagerSpec --debug
done

jbornemann · 2016-01-13T18:37:41Z

@sagarsane @jdigger @jazeren1 ready for review. I ran 4000 ./gradlew check on both master, and this branch overnight; and neither had any concurrency test failures. However, I ran 200 ./gradlew build on both master, and this branch; and master had 12 failures out of 200, and this branch had 0 failures out of 200.

I modified the script above a bit to test

SUCCESS=0
FAILURE=0
while [ 1 ]; do
  ./gradlew build --no-daemon
  if [ $? == 1 ]; then
    FAILURE=$(( FAILURE + 1))
  else
    SUCCESS=$(( SUCCESS + 1))
  fi
  echo "FAILURE count : ${FAILURE}"
  echo "SUCCESS count : ${SUCCESS}"
  sleep 1
done

sagarsane · 2016-01-13T18:54:54Z

...rc/main/groovy/com/twcable/grabbit/client/batch/workflows/impl/DefaultWorkFlowManager.groovy

 import java.util.concurrent.ConcurrentHashMap
-import java.util.concurrent.atomic.AtomicInteger
+import java.util.concurrent.atomic.AtomicInteger as JobUseCount


This seems super weird but I understand why this will be useful 😸 from code understanding perspective.

sagarsane · 2016-01-13T18:58:29Z

13:56:19.386 [pool-1-thread-3] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - (Re)initializing LauncherConfigs Map : [id3:0, id1:0, id2:0]

Condition not satisfied:

workflowLauncher.editConfigCallCount == workflowIds.size() * 2
|                |                   |  |           |      |
|                9                   |  |           3      6
|                                    |  [id1, id2, id3]
|                                    false
com.twcable.grabbit.client.batch.workflows.StubWorkflowLauncher@320e59bd

Expected :6

Actual   :9

  <Click to see difference>



    at com.twcable.grabbit.client.batch.workflows.WorkflowManagerSpec.Should manage multithreading correctly(WorkflowManagerSpec.groovy:63)


Process finished with exit code 255

So the first time I ran this in IntelliJ, I got the above error 😢 .. I tried running this multiple times after that (using Gradle and otherwise) and it passed ... :/

jbornemann · 2016-01-13T19:07:59Z

Whaa?

jbornemann · 2016-01-13T19:35:42Z

Don't suppose you captured a thread dump, did you? :S

sagarsane · 2016-01-13T19:35:57Z

I know 😭 I haven't been able to break it since then. I am going to try though.

sagarsane · 2016-01-13T19:43:15Z

Ok got it to break again.

Here are the details from the console :

Connected to the target VM, address: '127.0.0.1:54815', transport: 'socket'
14:36:57.998 [main] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Activate : LauncherConfigs Map : [:]
14:36:58.031 [pool-1-thread-5] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [:]
14:36:58.031 [pool-1-thread-9] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [:]
14:36:58.031 [pool-1-thread-5] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Putting id: id1 in Map
14:36:58.031 [pool-1-thread-5] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning off config : id1
14:36:58.034 [pool-1-thread-10] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.035 [pool-1-thread-8] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.034 [pool-1-thread-6] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.035 [pool-1-thread-4] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.035 [pool-1-thread-7] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.036 [pool-1-thread-3] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.036 [pool-1-thread-2] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.036 [pool-1-thread-1] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id1 and Map: [id1:1]
14:36:58.043 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:1]
14:36:58.043 [pool-1-thread-3] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:1]
14:36:58.043 [pool-1-thread-7] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:2]
14:36:58.043 [pool-1-thread-9] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:3]
14:36:58.043 [pool-1-thread-3] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:4]
14:36:58.043 [pool-1-thread-9] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Putting id: id2 in Map
14:36:58.043 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning off config : id2
14:36:58.043 [pool-1-thread-1] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:1]
14:36:58.043 [pool-1-thread-4] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:5, id2:1]
14:36:58.043 [pool-1-thread-1] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:5, id2:1]
14:36:58.044 [pool-1-thread-6] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:6, id2:1]
14:36:58.043 [pool-1-thread-2] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:1]
14:36:58.044 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:7, id2:1]
14:36:58.044 [pool-1-thread-8] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id1 is already processed. LauncherConfigs Map is : [id1:6, id2:1]
14:36:58.044 [pool-1-thread-1] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id1:6, id2:1]
14:36:58.044 [pool-1-thread-4] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:6, id2:1]
14:36:58.043 [pool-1-thread-3] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id1:4, id2:1]
14:36:58.043 [pool-1-thread-7] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:4, id2:1]
14:36:58.044 [pool-1-thread-4] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id1:10, id2:2]
14:36:58.044 [pool-1-thread-7] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id1:10, id2:3]
14:36:58.047 [pool-1-thread-4] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id1:10, id2:5]
14:36:58.047 [pool-1-thread-2] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:10, id2:5]
14:36:58.047 [pool-1-thread-4] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Putting id: id3 in Map
14:36:58.047 [pool-1-thread-8] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id3:1, id1:10, id2:5]
14:36:58.047 [pool-1-thread-10] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id1:10, id2:5]
14:36:58.047 [pool-1-thread-8] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id3:1, id1:10, id2:5]
14:36:58.047 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id3:1, id1:10, id2:5]
14:36:58.047 [pool-1-thread-1] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:1, id1:10, id2:6]
14:36:58.048 [pool-1-thread-8] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:1, id1:10, id2:7]
14:36:58.048 [pool-1-thread-1] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:1, id1:10, id2:7]
14:36:58.047 [pool-1-thread-3] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id1:10, id2:5]
14:36:58.048 [pool-1-thread-8] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:2, id1:10, id2:7]
14:36:58.048 [pool-1-thread-7] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:1, id1:10, id2:7]
14:36:58.048 [pool-1-thread-10] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:1, id1:10, id2:7]
14:36:58.048 [pool-1-thread-6] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id3:1, id1:10, id2:7]
14:36:58.048 [pool-1-thread-7] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:3, id1:10, id2:7]
14:36:58.047 [pool-1-thread-2] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id3:1, id1:10, id2:5]
14:36:58.047 [pool-1-thread-4] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning off config : id3
14:36:58.048 [pool-1-thread-6] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id3:3, id1:10, id2:7]
14:36:58.048 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:3, id1:10, id2:7]
14:36:58.048 [pool-1-thread-3] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:2, id1:10, id2:7]
14:36:58.048 [pool-1-thread-2] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:4, id1:10, id2:8]
14:36:58.048 [pool-1-thread-6] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:5, id1:10, id2:9]
14:36:58.048 [pool-1-thread-2] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:6, id1:10, id2:9]
14:36:58.048 [pool-1-thread-6] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:6, id1:10, id2:9]
14:36:58.058 [pool-1-thread-4] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id3
14:36:58.058 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id2
14:36:58.058 [pool-1-thread-5] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id1
14:36:58.058 [pool-1-thread-9] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id2 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.058 [pool-1-thread-4] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id3 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.059 [pool-1-thread-5] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id1 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.059 [pool-1-thread-9] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:8, id1:10, id2:9]
14:36:58.059 [pool-1-thread-5] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id2 and Map: [id3:8, id1:10, id2:9]
14:36:58.060 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:8, id1:10, id2:9]
14:36:58.060 [pool-1-thread-5] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id2 is already processed. LauncherConfigs Map is : [id3:8, id1:10, id2:9]
14:36:58.060 [pool-1-thread-5] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID: id3 and Map: [id3:9, id1:10, id2:10]
14:36:58.060 [pool-1-thread-5] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current ID : id3 is already processed. LauncherConfigs Map is : [id3:9, id1:10, id2:10]
14:36:58.096 [pool-1-thread-3] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:9, id1:9, id2:9]
14:36:58.124 [pool-1-thread-8] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:8, id1:8, id2:8]
14:36:58.137 [pool-1-thread-5] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:7, id1:7, id2:7]
14:36:58.142 [pool-1-thread-6] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:6, id1:6, id2:6]
14:36:58.196 [pool-1-thread-4] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:5, id1:5, id2:5]
14:36:58.213 [pool-1-thread-1] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:3, id1:3, id2:3]
14:36:58.213 [pool-1-thread-2] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:3, id1:3, id2:3]
14:36:58.248 [pool-1-thread-7] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:2, id1:2, id2:2]
14:36:58.259 [pool-1-thread-10] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:0, id1:0, id2:0]
14:36:58.259 [pool-1-thread-9] DEBUG c.t.g.c.b.w.i.DefaultWorkFlowManager - LauncherConfig in turnOn() is : [id3:0, id1:0, id2:0]
14:36:58.259 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning on configId : id3
14:36:58.259 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning on configId : id3
14:36:58.259 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id3
14:36:58.259 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id3
14:36:58.259 [pool-1-thread-9] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id3 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.259 [pool-1-thread-10] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id3 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.259 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning on configId : id1
14:36:58.260 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning on configId : id1
14:36:58.260 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id1
14:36:58.260 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id1
14:36:58.260 [pool-1-thread-9] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id1 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.260 [pool-1-thread-10] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id1 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.260 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning on configId : id2
14:36:58.260 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Turning on configId : id2
14:36:58.260 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Editing config for id:  id2
14:36:58.260 [pool-1-thread-9] INFO  c.t.g.c.b.w.StubWorkflowLauncher - Editing configEntry with ID : id2 with new entry: com.day.cq.workflow.launcher.ConfigEntry@30
14:36:58.260 [pool-1-thread-9] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - (Re)initializing LauncherConfigs Map : [id3:0, id1:0, id2:0]
14:36:58.260 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - Current Workflow Launcher : id2 is already Turned On. No-op
14:36:58.260 [pool-1-thread-10] INFO  c.t.g.c.b.w.i.DefaultWorkFlowManager - (Re)initializing LauncherConfigs Map : [:]

Condition not satisfied:

workflowLauncher.editConfigCallCount == workflowIds.size() * 2
|                |                   |  |           |      |
|                8                   |  |           3      6
|                                    |  [id1, id2, id3]
|                                    false
com.twcable.grabbit.client.batch.workflows.StubWorkflowLauncher@2ed50eb9

Expected :6

Actual   :8

  <Click to see difference>



    at com.twcable.grabbit.client.batch.workflows.WorkflowManagerSpec.Should manage multithreading correctly(WorkflowManagerSpec.groovy:63)


Disconnected from the target VM, address: '127.0.0.1:54815', transport: 'socket'

Process finished with exit code 255

jbornemann · 2016-01-13T23:23:47Z

@sagarsane that's gotta be from master :) My log statements are different, and plus I renamed LauncherConfigsMap to workflowSemaphore

jbornemann · 2016-01-13T23:24:48Z

@masroormohammed , do you mind testing this from a functional perspective? @sagarsane tells me you understand this part. Looks good from my angle

masroormohammed · 2016-01-18T21:37:01Z

+1 CR and test

jbornemann · 2016-01-19T15:21:18Z

Thanks Masroor!

jdigger added the in progress label Jan 12, 2016

Cleaned up WorkflowManager, and work to avoid concurrency issues

e72171c

jbornemann force-pushed the fix-workflow-manager-concurrency branch from 87a0faf to e72171c Compare January 12, 2016 22:26

jbornemann added the Review label Jan 13, 2016

sagarsane reviewed Jan 13, 2016
View reviewed changes

This was referenced Jan 14, 2016

WorkflowManagerSpec "Should manage multithreading correctly" fails intermittently #38

Closed

Grabbit fails to push content when using workflowConfigs for nodes without workflow #36

Closed

jbornemann merged commit e72171c into master Jan 19, 2016

jbornemann deleted the fix-workflow-manager-concurrency branch January 19, 2016 15:25

jdigger removed in progress Review labels Jan 19, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix workflow manager concurrency #97

Fix workflow manager concurrency #97

jbornemann commented Jan 12, 2016

jbornemann commented Jan 12, 2016

jbornemann commented Jan 13, 2016

sagarsane Jan 13, 2016

sagarsane commented Jan 13, 2016

jbornemann commented Jan 13, 2016

jbornemann commented Jan 13, 2016

sagarsane commented Jan 13, 2016

sagarsane commented Jan 13, 2016

jbornemann commented Jan 13, 2016

jbornemann commented Jan 13, 2016

masroormohammed commented Jan 18, 2016

jbornemann commented Jan 19, 2016

Fix workflow manager concurrency #97

Fix workflow manager concurrency #97

Conversation

jbornemann commented Jan 12, 2016

jbornemann commented Jan 12, 2016

jbornemann commented Jan 13, 2016

sagarsane Jan 13, 2016

Choose a reason for hiding this comment

sagarsane commented Jan 13, 2016

jbornemann commented Jan 13, 2016

jbornemann commented Jan 13, 2016

sagarsane commented Jan 13, 2016

sagarsane commented Jan 13, 2016

jbornemann commented Jan 13, 2016

jbornemann commented Jan 13, 2016

masroormohammed commented Jan 18, 2016

jbornemann commented Jan 19, 2016