Automation for Jira - サードパーティ アドオンを使用しているため、自動化実行スレッドがスタックする

要約

この記事では、サードパーティ アドオンがスレッドをブロックしているために Automation for Jira (A4J) のすべてのルールがトリガーされなくなるいくつかのシナリオ、それらを区別する方法、および修正方法について説明します。

観察された現象は次のとおりです。

• さまざまな A4J ルールが、新しい課題が作成または更新されたときにトリガーされるように構成されています。

• これらすべてのルールが同時にトリガーされなくなりました。たとえば、「課題の作成」イベントでトリガーされるべきルールは、新しい課題が最近作成されたとしても監査ログには何も表示されません。

• トリガーが構成された A4J ルールで [Execute this rule immediately when the rule is triggered (ルールがトリガーされた場合、直ちにこのルールを実行する)] オプションがオンになっている場合、そのルールはトリガーされます。ただし、このオプションをオフにすると (既定でオフ)、このようなルールはトリガーされません。

診断

シナリオ 1

• 次の SQL クエリを実行して A4J キューのサイズを確認すると、イベントが処理されずにキューに溜まっていることがわかります。

• 問題の発生中にスレッド ダンプを収集すると、次のことがわかります。

• キューからのイベントを処理してルールをトリガーするスレッド automation-rule-executor:thread-X がすべて Blocked ステータスでスタックしている

• デッドロックがある

  • A4J ルール実行スレッド 1、2、3、4、5 は Blocked 状態で、同じロックを待機しています (下の例では <0x00000000154fe597>)。

    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

  • 6 番目の A4J ルール実行スレッド (automation-rule-executor:thread-6) が、他の A4J スレッドが待機しているロック <0x00000000154fe597> を保持しています。一方で、この 6 番目のスレッドも、2 番目の A4J ルール実行スレッド (automation-rule-executor:thread-2)によって保持されているロック (下の例では <0x000000005201b552>) を待機しています。

    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)

  • 止まっているスレッドのスタック トレースを確認すると、それらがすべて非常に似ていて、いずれもサードパーティ アドオンに属するクラスを呼び出していることがわかります。(特定のものだけでなく) さまざまなサードパーティ アドオンがこの状況につながる可能性があるため、サードパーティ アドオン クラスの名前が com.some3rdpartyaddon.jira.plugin という一般的な名前に置き換えられた点に注目してください。

シナリオ 2

• 次の SQL クエリを実行して A4J キューのサイズを確認すると、イベントが処理されずにキューに溜まっていることがわかります。

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

• 問題の発生中にスレッド ダンプを収集すると、次のことがわかります。

  • ほとんどの A4J 実行スレッドが TIMED_WAITING 状態でスタックしています。

    

  • 各 A4J 実行スレッドのスタック トレースを見ると、サードパーティ アドオンのクラスが原因で、何らかのデータベース操作を実行しようとして両方ともスタックしていることがわかります。(特定のものだけでなく) さまざまなサードパーティ アドオンがこの状況につながる可能性があるため、サードパーティ アドオン クラスの名前が com.some3rdpartyaddon.jira.plugin という一般的な名前に置き換えられた点に注目してください。

    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

原因

シナリオ 1 の原因

この問題を引き起こす正確な条件は不明です。現時点でわかっていることは以下のとおりです。

• A4J のルール実行スレッドがサードパーティ アドオンのクラスを呼び出している (スレッド ダンプで見つかったクラスに基づいて特定)

• 何らかの理由により、このアドオンが原因でルール実行スレッドを互いのロック (リソース) を待機している

• 最終的に、すべてのルール実行スレッドがデッドロック状態になり、すべての自動化ルールがトリガーされなくなる

[Execute this rule immediately when the rule is triggered (ルールがトリガーされた場合、直ちにこのルールを実行する)] オプションをオンにして構成された A4J ルールが影響を受けない理由は、トリガーされて実行される A4J キューと A4J ルール実行スレッドにこのようなルールが依存していないためです。このようなルールはキューを迂回して直ちに実行されます。

シナリオ 2 の原因

この問題を引き起こす正確な条件は不明です。現時点でわかっていることは以下のとおりです。

• A4J のルール実行スレッドがサードパーティ アドオンのクラスを呼び出している (スレッド ダンプで見つかったクラスに基づいて特定)

• このアドオンは終了することがない何らかのデータベース操作を実行し、A4J 実行スレッドを無期限の TIMED_WAITING 状態にしている

• 最終的に、ルール実行スレッドのすべてまたはほとんどが同じ状態で終了し、すべての自動化ルールがトリガーされなくなる

[Execute this rule immediately when the rule is triggered (ルールがトリガーされた場合、直ちにこのルールを実行する)] オプションをオンにして構成された A4J ルールが影響を受けない理由は、トリガーされて実行される A4J キューと A4J ルール実行スレッドにこのようなルールが依存していないためです。このようなルールはキューを迂回して直ちに実行されます。

ソリューション

上記の両方のシナリオで解決策は同じ

解決策は、以下の手順に従って、診断ステップで特定された問題のあるサードパーティ アドオンを無効にし、Jira アプリケーションを再起動することです。

1. メインテナンス ウィンドウを計画します。

2. ⚙ > [アプリの管理] > [アプリの管理] に移動

3. 対象のアドオンを探して無効にします。

4. Jira アプリケーションを再起動します。

サードパーティ アドオンはアトラシアンでサポートしていないため、アドオンを使用することが業務上不可欠な場合は、アドオン サポート チームに連絡して追加のサポートを受けることをお勧めします。