[JRASERVER-62958] Enabling access logging might cause JIRA to stall

Type: Bug
Resolution: Fixed
Priority: High (View bug fix roadmap)
Fix Version/s: 9.5.0
Affects Version/s: 6.4.14, 7.2.2, 9.4.17
Component/s: Administration - Others
Labels:
- affects-server
- l1l2
- pse-request
- raid

Introduced in Version:
6.04
Support reference count:
76
Symptom Severity:
Severity 1 - Critical
UIS:
34
Bug Fix Policy:
View Atlassian Server bug fix policy
Current Status:

Hide

Atlassian Update – 30.01.2025

Dear Customers,

In Jira 9.5.0 we have upgraded Jira to use log4j 2 instead of log4j 1.
The behavior mentioned in this ticket does not occur in log4j 2.

Best regards

Filip Nowak
Software Engineer, Jira DC

Show
Atlassian Update – 30.01.2025 Dear Customers, In Jira 9.5.0 we have upgraded Jira to use log4j 2 instead of log4j 1. The behavior mentioned in this ticket does not occur in log4j 2. Best regards Filip Nowak Software Engineer, Jira DC

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

Enable Access logging
Generate high load
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.

is related to

JRASERVER-71759 WARN: Unexpected un-versioned operation added for processing ... for comments&worklogs

Closed

JRASERVER-71457 Enabling the debugging package com.atlassian.jira.security (or any sub-package) might cause JIRA to stall

Gathering Impact

relates to

JRASERVER-62959 StackTraceInfo Class are initialised multiple times on stack trace logging

Closed

JRASERVER-70908 Manually deleting HTTP Access Logs cause them to not be recreated before an application restart.

Gathering Impact

JRASERVER-62838 Upgrade to log4j 2.x

Closed

is duplicated by: MNSTR-6399 Loading...

mentioned in: Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...

was cloned as: RAID-171 Loading...

(1 is duplicated by, 10 mentioned in, 1 was cloned as)

Andriy Yakovlev [Atlassian] added a comment - 16/Jan/2020 2:47 PM

also related https://issues.apache.org/jira/browse/LOG4J2-2490

many thread blocked when logging a lot of exception, I found the reason is a java optimize to reflection.

The first 15 runs (by default) of your reflected method is called using JNI; after that, bytecode is generated and calling that reflected method would perform identically to calling that method directly in Java code.

ThrowableProxy.toExtendedStackTrace, the method will load class, and get jar package info, when it process a optimized reflected method, it will use classloaders but never found the class such as sun.reflect.GeneratedMethodAccessor119, in this process it will try to load class from jar file every time and spend so much cost. Worse, have a lock when loadClass, when many threads run this method, thread blocked.

Andriy Yakovlev [Atlassian] added a comment - 16/Jan/2020 2:47 PM also related https://issues.apache.org/jira/browse/LOG4J2-2490 many thread blocked when logging a lot of exception, I found the reason is a java optimize to reflection. The first 15 runs (by default) of your reflected method is called using JNI; after that, bytecode is generated and calling that reflected method would perform identically to calling that method directly in Java code. ThrowableProxy.toExtendedStackTrace, the method will load class, and get jar package info, when it process a optimized reflected method, it will use classloaders but never found the class such as sun.reflect.GeneratedMethodAccessor119, in this process it will try to load class from jar file every time and spend so much cost. Worse, have a lock when loadClass, when many threads run this method, thread blocked.

John Price added a comment - 15/May/2019 2:13 PM

I believe this may have caused a crash of our main client-facing Jira yesterday. An admin accidentally changed a field config, which generated a ton of logged errors, and JavaMelody thread list showed 100+ threads BLOCKED while trying to write to log appender. We do have Access Logging on so seems suspect.

John Price added a comment - 15/May/2019 2:13 PM I believe this may have caused a crash of our main client-facing Jira yesterday. An admin accidentally changed a field config, which generated a ton of logged errors, and JavaMelody thread list showed 100+ threads BLOCKED while trying to write to log appender. We do have Access Logging on so seems suspect.

Details

Description

Summary

Steps to Reproduce

Expected Results

Actual Results

Thread dump details

Notes

Workaround

Attachments

Issue Links

Forms

Activity

Collapse comment: Andriy Yakovlev [Atlassian] added a comment - 16/Jan/2020 2:47 PM

Expand comment: Andriy Yakovlev [Atlassian] added a comment - 16/Jan/2020 2:47 PM

Collapse comment: John Price added a comment - 15/May/2019 2:13 PM

Expand comment: John Price added a comment - 15/May/2019 2:13 PM

People

Dates