[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)

Calum Leslie made changes - 12/Feb/2025 2:14 PM

Remote Link

New: This issue links to "Page (Confluence)" [ 988018 ]

Filip Nowak made changes - 30/Jan/2025 11:41 AM

Fix Version/s

New: 9.5.0 [ 102892 ]

Filip Nowak made changes - 30/Jan/2025 11:41 AM

Current Status

New: {panel:title=Atlassian Update – 30.01.2025|borderStyle=solid|borderColor=#deebff|titleBGColor=#deebff|bgColor=#deebff}
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
{panel}

Filip Nowak made changes - 30/Jan/2025 11:37 AM

Resolution		New: Fixed [ 1 ]
Status	Original: In Progress [ 3 ]	New: Closed [ 6 ]

Filip Nowak made changes - 30/Jan/2025 11:37 AM

Status

Original: Gathering Impact [ 12072 ]

New: In Progress [ 3 ]

Filip Nowak made changes - 30/Jan/2025 11:36 AM

Assignee

New: Filip Nowak [ 15609d8ba305 ]

SET Analytics Bot made changes - 22/Dec/2024 2:19 AM

UIS

Original: 33

New: 34

SET Analytics Bot made changes - 21/Dec/2024 4:11 AM

Support reference count

Original: 74

New: 76

Saima Ali Sayyed made changes - 20/Dec/2024 11:17 AM

Affects Version/s

New: 9.4.17 [ 107008 ]

SET Analytics Bot made changes - 13/Dec/2024 2:14 AM

UIS

Original: 32

New: 33

Assignee:: Filip Nowak

Reporter:: Andriy Yakovlev [Atlassian]

Affected customers:: 13 This affects my team

Watchers:: 36 Start watching this issue

Created:: 26/Oct/2016 11:32 AM

Updated:: 12/Feb/2025 2:14 PM

Resolved:: 30/Jan/2025 11:37 AM

Details

Description

Summary

Steps to Reproduce

Expected Results

Actual Results

Thread dump details

Notes

Workaround

Attachments

Issue Links

Forms

Activity

People

Dates