Automation for Jira - The automation executor threads are stuck because of the usage of a 3rd party add-on

Summary

This article describes a few scenarios where all rules from Automation for Jira (A4J) stop being triggered due to a 3rd party add-on blocking the threads, how to identify them, and how to fix them.

The observed symptoms are the following:

• Various A4J rules are configured to be triggered when a new issue is created or updated

• For all these rules, they stopped being triggered at the same time. For example, the rules that should be triggered on the "Create Issue" event don't show anything in the Audit log even though new issues were recently created:

• Note that, for any A4J rule configured with a trigger that has the option Execute this rule immediately when the rule is triggered ticked, this rule gets triggered. However, if this option is unticked (which is the default configured), such rule is not triggered

Diagnosis

Scenario 1:

• When the following SQL query is executed to check the size of the A4J queue, we can see that the events keep piling up in the queue without being processed:

• When collecting thread dumps while the issue is happening, we can make the following observations:

• All the threads automation-rule-executor:thread-X which are responsible to process events from the queue and trigger the rules are stuck in the Blocked status

• There is a deadlock

  • A4J rule executor threads 1, 2, 3, 4, 5 are in the Blocked state, waiting for the same lock (<0x00000000154fe597> in the example below):

    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 "automation-rule-executor:thread-1" daemon prio=5 tid=0x00000000000d3cf0 nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.hashCode(Unknown Source) - waiting to lock <0x00000000154fe597> (a java.util.Vector) owned by automation-rule-executor:thread-6 id=0x00000000000d3d20 "automation-rule-executor:thread-2" daemon prio=5 tid=0x00000000000d3cfa nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.listIterator(Unknown Source) - waiting to lock <0x00000000154fe597> (a java.util.Vector) owned by automation-rule-executor:thread-6 id=0x00000000000d3d20 at java.base@11.0.13/java.util.AbstractList.equals(Unknown Source) at java.base@11.0.13/java.util.Vector.equals(Unknown Source) - locked <0x000000005201b552> (a java.util.Vector) at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38) "automation-rule-executor:thread-3" daemon prio=5 tid=0x00000000000d3cfb nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.hashCode(Unknown Source) - waiting to lock <0x00000000154fe597> (a java.util.Vector) owned by automation-rule-executor:thread-6 id=0x00000000000d3d20 "automation-rule-executor:thread-4" daemon prio=5 tid=0x00000000000d3cfc nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.hashCode(Unknown Source) - waiting to lock <0x00000000154fe597> (a java.util.Vector) owned by automation-rule-executor:thread-6 id=0x00000000000d3d20 "automation-rule-executor:thread-5" daemon prio=5 tid=0x00000000000d3d1f nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.hashCode(Unknown Source) - waiting to lock <0x00000000154fe597> (a java.util.Vector) owned by automation-rule-executor:thread-6 id=0x00000000000d3d20

  • The 6th A4J rule executor thread (automation-rule-executor:thread-6) is holding that lock <0x00000000154fe597> that the other A4J threads are waiting for. But this 6th thread is also waiting for a lock (<0x000000005201b552> in the example below) held by the 2nd A4J rule executor thread (automation-rule-executor:thread-2)

    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 "automation-rule-executor:thread-6" daemon prio=5 tid=0x00000000000d3d20 nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.listIterator(Unknown Source) - waiting to lock <0x000000005201b552> (a java.util.Vector) owned by automation-rule-executor:thread-2 id=0x00000000000d3cfa at java.base@11.0.13/java.util.AbstractList.equals(Unknown Source) at java.base@11.0.13/java.util.Vector.equals(Unknown Source) - locked <0x00000000154fe597> (a java.util.Vector) at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38) at org.apache.fop.fo.properties.ListProperty.equals(ListProperty.java:123) "automation-rule-executor:thread-2" daemon prio=5 tid=0x00000000000d3cfa nid=0 waiting for monitor entry java.lang.Thread.State: BLOCKED (on object monitor) at java.base@11.0.13/java.util.Vector.listIterator(Unknown Source) - waiting to lock <0x00000000154fe597> (a java.util.Vector) owned by automation-rule-executor:thread-6 id=0x00000000000d3d20 at java.base@11.0.13/java.util.AbstractList.equals(Unknown Source) at java.base@11.0.13/java.util.Vector.equals(Unknown Source) - locked <0x000000005201b552> (a java.util.Vector) at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38)

  • If we check the stack trace from any thread that's stuck, we can see that they are all very similar and that they all end up making a call to a class which belongs to a 3rd party add-on. Please note that the name of the 3rd party add-on class was replaced by the generic name com.some3rdpartyaddon.jira.plugin, since various 3rd party add-ons could lead to this situation (and not just a specific one):

Scenario 2:

• When the following SQL query is executed to check the size of the A4J queue, we can see that the events keep piling up in the queue without being processed:

  1 2 3 4 5 select count (*) from "AO_589059_AUTOMATION_QUEUE"; count ------- 47423 (1 row)

• When collecting thread dumps while the issue is happening, we can make the following observations:

  • Most A4J execution threads are stuck in the TIMED_WAITING state:

    

  • If we look at the stack trace of each A4J executor thread, we can see that they are both stuck trying to perform some database operation, which was caused by a class coming from a 3rd party add-on. Please note that the name of the 3rd party add-on class was replaced by the generic name com.some3rdpartyaddon.jira.plugin, since various 3rd party add-ons could lead to this situation (and not just a specific one)

    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 20:13:36 - automation-rule-executor:thread-1 State:TIMED-WAITING CPU usage:0.00% Running for: 0:00.00 Waiting for This thread is waiting for notification on lock [0x6373d1838] without an owner Locks held This thread does not hold any locks Stack trace java.lang.Object.wait(java.base@11.0.13/Native Method) org.postgresql.jdbc.PgStatement.killTimerTask(PgStatement.java:1034) org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:484) org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401) org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322) org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308) org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284) org.postgresql.jdbc.PgStatement.executeUpdate(PgStatement.java:258) org.apache.commons.dbcp2.DelegatingStatement.executeUpdate(DelegatingStatement.java:234) org.apache.commons.dbcp2.DelegatingStatement.executeUpdate(DelegatingStatement.java:234) com.atlassian.jira.ofbiz.sql.StatementWrapper.executeUpdate(StatementWrapper.java:29) com.atlassian.jira.diagnostic.connection.DiagnosticStatement.lambda$executeUpdate$8(DiagnosticStatement.java:70) com.atlassian.jira.diagnostic.connection.DiagnosticStatement$$Lambda$5027/0x0000000804584040.execute(Unknown Source) com.atlassian.diagnostics.internal.platform.monitor.db.DefaultDatabaseDiagnosticsCollector.recordExecutionTime(DefaultDatabaseDiagnosticsCollector.java:91) com.atlassian.jira.diagnostic.connection.DatabaseDiagnosticsCollectorDelegate.recordExecutionTime(DatabaseDiagnosticsCollectorDelegate.java:62) com.atlassian.jira.diagnostic.connection.DiagnosticStatement.executeUpdate(DiagnosticStatement.java:70) (TRIMMED) com.some3rdpartyaddon.jira.plugin.someclass(XXXXXXXX.java:114) com.some3rdpartyaddon.jira.plugin.someclass(XXXXXXXX.java:139) (TRIMMED) com.atlassian.jira.event.issue.IssueEventListenerHandler$IssueEventInvoker.invoke(IssueEventListenerHandler.java:43) com.atlassian.diagnostics.internal.platform.monitor.event.EventSystemMonitor.invokeMonitored(EventSystemMonitor.java:105) com.atlassian.diagnostics.internal.platform.monitor.event.MonitoredListenerInvoker.invoke(MonitoredListenerInvoker.java:38) com.atlassian.event.internal.ComparableListenerInvoker.invoke(ComparableListenerInvoker.java:48) com.atlassian.event.internal.AsynchronousAbleEventDispatcher.lambda$null$0(AsynchronousAbleEventDispatcher.java:37) (TRIMMED) com.codebarrel.automation.rulecomponent.jira.action.edit.EditIssueActionExecutor.executeWithIssues(EditIssueActionExecutor.java:79) com.codebarrel.automation.api.component.executor.IssueRequiredExecutor.execute(IssueRequiredExecutor.java:35) com.codebarrel.automation.api.component.executor.IssueRequiredExecutor.execute(IssueRequiredExecutor.java:18) com.codebarrel.automation.api.service.ComponentChainImpl.doExecute(ComponentChainImpl.java:76) com.codebarrel.automation.api.service.SingleRuleExecutorServiceImpl.execute(SingleRuleExecutorServiceImpl.java:229) com.codebarrel.jira.plugin.automation.queue.JiraAutomationQueueExecutor.lambda$processClaimedItem$3(JiraAutomationQueueExecutor.java:275) (TRIMMED) com.codebarrel.jira.plugin.automation.queue.JiraAutomationQueueExec

Cause

Cause for Scenario 1:

The exact conditions that trigger this issue are unknown. All we can tell is that:

• the rule executor threads from A4J are making calls to classes coming from the 3rd party add-on (to be identified based on the class found in the thread dumps)

• this add-on somehow makes the rule executor threads wait for each other's lock (resource)

• ultimately all the rule executor threads end up in a deadlock situation, causing all the automation rule to stop being triggered

The reason why A4J rules configured with the option Execute this rule immediately when the rule is triggered ticked are not impacted is because such rule does not rely on the A4J queue and the A4J rule executor threads to be triggered and executed. Such rules bypass the queue and are executed immediately.

Cause for Scenario 2:

The exact conditions that trigger this issue are unknown. All we can tell is that:

• the rule executor threads from A4J are making calls to classes coming from the 3rd party add-on (to be identified based on the class found in the thread dumps)

• this add-on performs some database operation that never ends, putting the A4J executor threads into an indefinite TIMED_WAITING state

• ultimately all or most of the rule executor threads end in that same state, causing all the automation rule to stop being triggered

The reason why A4J rules configured with the option Execute this rule immediately when the rule is triggered ticked are not impacted is because such rule does not rely on the A4J queue and the A4J rule executor threads to be triggered and executed. Such rules bypass the queue and are executed immediately.

Solution

For both the above scenarios

The solution is to disable the problematic 3rd party add-on identified during the diagnosis steps and re-start the Jira application by following the steps below:

1. Schedule some maintenance window

2. Go to ⚙ > Manage Apps > Manage Apps

3. Look for the add-on and disable it

4. Re-start the Jira application

If being able to use the add-on is critical for your operations, then we recommend to reach out to the add-on support team for further assistance, since 3rd party add-son are not supported by Atlassian.