Enabling analytics prevents Jira from shutting down cleanly

XMLWordPrintable

    • Type: Bug
    • Resolution: Cannot Reproduce
    • Priority: Low
    • None
    • Affects Version/s: 8.5.3
    • Component/s: Tomcat
    • 8.05
    • 3
    • Severity 3 - Minor

      Issue Summary

      The Atlassian Analytics plugin prevents Tomcat from cleanly shutting down, as it leaves "Analytics" non-daemon threads that are not able to be stopped by the shutdown process. 

      This results in the message in the log always, regardless of the shutdown timeout:

      Tomcat did not stop in time.
To aid diagnostics a thread dump has been written to standard out.
Killing Tomcat with the PID: 12726
The Tomcat process has been killed.

      Impact
      If Tomcat is able to shutdown all threads except for the Analytics threads, there is no impact.

      The concern is that this problem will mask an administrators ability to set the shutdown value correctly since Jira will never cleanly shutdown. If Jira terminated while shutting down but is actually doing some useful operation, there may be a risk that operation is terminated half way through. Therefore, we should always aim for a graceful shutdown. Also, it will delay the shutdown time as the script will always wait for the timeout value to be reached before existing.

      Steps to Reproduce

      1. On Jira 8.5.3, Jira Admin -> System -> Analytics -> Enable
      2. Edit JIRAINST/bin/stop-jira.sh and modify the shutdown timeout on following two lines to 300. This allows enough time for Tomcat to attempt a clean shutdown 
        exec $PRGDIR/shutdown.sh 300 -force $@
$sucmd -m $JIRA_USER -c "$PRGDIR/shutdown.sh 300 -force $@"
      1. On the console, execute JIRAINST/bin/stop-jira.sh
      2. The script will wait 300 seconds, then eventually terminate due to stuck Analytics threads: 
        The Tomcat process has been killed.

      Expected Results

      Jira shuts down cleanly without having to be killed:

      Tomcat stopped.

      Actual Results

      The script will wait indefinitely for Tomcat to shutdown until the timeout value in stop-jira.sh has been reached. The script will then forcefully kill tomcat

      Tomcat did not stop in time.
To aid diagnostics a thread dump has been written to standard out.
Killing Tomcat with the PID: 12726
The Tomcat process has been killed.

       

      org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads() will alert that Analytics threads to not stop, and a thread dump will be written to catalina.out showing the non-daemon Analytics threads:

      07-Apr-2020 11:28:14.660 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [j853] appears to have started a thread named [Analytics] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
 java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 com.segment.analytics.Platform$1$1.run(Platform.java:45)
 java.lang.Thread.run(Thread.java:748)

07-Apr-2020 11:28:14.677 INFO [main] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8853"]
07-Apr-2020 11:28:14.681 INFO [main] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8853"]
2020-04-07 11:29:33
Full thread dump OpenJDK 64-Bit Server VM (25.202-b08 mixed mode):

"DestroyJavaVM" #345 prio=5 os_prio=31 tid=0x00007fd14d4ee000 nid=0x2303 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Java2D Disposer" #309 daemon prio=10 os_prio=31 tid=0x00007fd146abb800 nid=0xb307 in Object.wait() [0x0000700011806000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x0000000758fe8e08> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at sun.java2d.Disposer.run(Disposer.java:148)
	at java.lang.Thread.run(Thread.java:748)

"Analytics" #215 prio=1 os_prio=31 tid=0x00007fd14bad5000 nid=0x1570f waiting on condition [0x0000700013151000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007564977e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at com.segment.analytics.Platform$1$1.run(Platform.java:45)
	at java.lang.Thread.run(Thread.java:748)

"Analytics" #213 prio=1 os_prio=31 tid=0x00007fd1474e9000 nid=0x1ed03 waiting on condition [0x0000700014181000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007564d6fc8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at com.segment.analytics.Platform$1$1.run(Platform.java:45)
	at java.lang.Thread.run(Thread.java:748)

       

      Workaround

      1. Disable Analytics in Jira Admin -> System -> Analytics -> Disable
      2. Modify the timeouts in stop-jira.sh to a reasonable value that gives Tomcat enough time to stop cleanly. This will vary depending on the environment and plugins installed 
        exec $PRGDIR/shutdown.sh 120 -force $@ 
$sucmd -m $JIRA_USER -c "$PRGDIR/shutdown.sh 120 -force $@"
      3. Stop and start Jira to apply the change
      4. Stop Jira via ./stop-jira.sh and measure success

       Note that Analytics threads will hang around until the Jira service is restarted. So, to validate the change, please reboot at least once before checking for success

       

            Assignee:
            Unassigned
            Reporter:
            Alex [Atlassian,PSE]
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: