Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-62958

Enabling access logging might cause JIRA to stall

XMLWordPrintable

      Summary

      Enabling Access logging (at [ Administration > System > Logging & Profiling ] ) might cause JIRA to stall. Incoming thread will be fighting for org.apache.log4j.Logger lock in AccessLogFilter
      Those logs will be written into atlassian-jira-http-access.log file in <JIRA_HOME>/logs/ folder.

      Steps to Reproduce

      1. Enable Access logging
      2. Generate high load
      3. Start active logging something in different thread.

      Expected Results

      JIRA works fine

      Actual Results

      JIRA stalls.

      • Almost all incoming http threads are blocked waiting to obtain the logger lock to log Access log data from AccessLogFilter - LockID_1
      • Thread http1 hold the lock LockID_1, but it waits for another lock LockID_2
      • Thread http2 holds the lock LockID_2 and does slow execution of some other task during that.
      Thread dump details

      Example of one the threads waiting for LockID_1:

      http-nio-8080-exec-299" #41569 daemon prio=5 tid=0x00007f41c4090000 nid=0x36b9 waiting for monitor entry [0x00007f40c7adc000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:204)
	- waiting to lock <0x000000040135e018> (a org.apache.log4j.Logger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
	at com.atlassian.jira.web.filters.accesslog.AccessLogFilter.preFilterCallStep(AccessLogFilter.java:194)
...

      Thread http1

      "http-nio-8080-exec-189" #25297 daemon prio=5 tid=0x00007f41c4056800 nid=0x28f8 waiting for monitor entry [0x00007f40c9045000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
	- waiting to lock <0x0000000401138288> (a org.apache.log4j.RollingFileAppender)
	at com.atlassian.jira.logging.JiraHomeAppender.doAppend(JiraHomeAppender.java:206)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	- locked <0x000000040135e018> (a org.apache.log4j.Logger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
...

      Thread http2:

      "http-nio-8080-exec-243 uri:/secure/admin/views/issuefields/screens/viewfieldscreens.jsp " #25366 daemon prio=5 tid=0x00007f41b8055800 nid=0x293d runnable [0x00007f3ec4d7c000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.Throwable.fillInStackTrace(Native Method)
	at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
	- locked <0x000000077805e9f8> (a java.lang.ClassNotFoundException)
	at java.lang.Throwable. (Throwable.java:287)
	at java.lang.Exception. (Exception.java:84)
	at java.lang.ReflectiveOperationException. (ReflectiveOperationException.java:75)
	at java.lang.ClassNotFoundException. (ClassNotFoundException.java:82)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
	at org.apache.catalina.loader.WebappClassLoaderBase.findClass(WebappClassLoaderBase.java:843)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1274)
	- locked <0x0000000401a8d810> (a org.apache.catalina.loader.WebappClassLoader)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1139)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:264)
	at org.apache.logging.log4j.util.LoaderUtil.loadClass(LoaderUtil.java:109)
	at org.apache.logging.log4j.core.util.Loader.loadClass(Loader.java:52)
	at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:495)
	at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:629)
	at org.apache.logging.log4j.core.impl.ThrowableProxy. (ThrowableProxy.java:111)
	at com.atlassian.logging.log4j.StackTraceInfo.buildPackagingRepresentation(StackTraceInfo.java:145)
	at com.atlassian.logging.log4j.StackTraceInfo.buildThrowableStrRep(StackTraceInfo.java:106)
	at com.atlassian.logging.log4j.StackTraceInfo. (StackTraceInfo.java:43)
	at com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep(FilteredPatternLayout.java:359)
	at com.atlassian.logging.log4j.FilteredPatternLayout.formatStackTrace(FilteredPatternLayout.java:336)
	at com.atlassian.logging.log4j.FilteredPatternLayout.format(FilteredPatternLayout.java:330)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
	at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:276)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	- locked <0x0000000401138288> (a org.apache.log4j.RollingFileAppender)
	at com.atlassian.jira.logging.JiraHomeAppender.doAppend(JiraHomeAppender.java:206)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	- locked <0x000000040113de30> (a org.apache.log4j.Logger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
...

      Notes

      Workaround

      Disable access logging.

              Unassigned Unassigned
              ayakovlev@atlassian.com Andriy Yakovlev [Atlassian]
              Votes:
              12 Vote for this issue
              Watchers:
              33 Start watching this issue

                Created:
                Updated: