Summary

Enabling com.atlassian.jira.security (at [ Administration > System > Logging & Profiling ] ) might cause JIRA to stall.

Incoming thread will be fighting for org.apache.log4j.Logger lock in workflowPermissionCheck

Those logs will be written into atlassian-jira.log file in <JIRA_HOME>/logs/ folder.

Steps to Reproduce

1. Go to ⚙ > System > Log and profiling
   1. Click on "Configure logging level for another package."
   2. Use "com.atlassian.jira.security" as the package name, and select "DEBUG" for the "Logging Level"
2. Generate a high load of activity in Jira related to issues (create issues, edit issue, etc...)

Expected Results

Jira works fine

Actual Results

Jira might eventually become unresponsive, as almost all incoming http threads are blocked waiting to obtain the logger lock to log debugging information into the file atlassian-jira.log

Thread dump details

Looking into thread dumps, we can see that the same exact pattern keeps repeating:

• more than 140 threads are waiting for the same lock and try to write into the Jira log files:

  "http-nio-8080-exec-167 url:/rest/gadgets/1...reated.vs.resolved url:/rest/api/2/mypermissions username:q1057533" #284713 daemon prio=5 os_prio=0 tid=0x00007f626c022800 nid=0xb633 waiting for monitor entry [0x00007f6008b4e000]
     java.lang.Thread.State: BLOCKED (on object monitor)
  	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
  	- waiting to lock <0x00000003c14b8448> (a org.apache.log4j.RollingFileAppender)
  	at com.atlassian.jira.logging.JiraHomeAppender.doAppend(JiraHomeAppender.java:206)
  	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:69)
  	at org.apache.log4j.Category.callAppenders(Category.java:219)
  	at org.apache.log4j.Category.forcedLog(Category.java:402)
  	at org.apache.log4j.Category.log(Category.java:869)
  	at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:210)
  	at com.atlassian.jira.security.WorkflowBasedPermissionManager.workflowPermissionCheck(WorkflowBasedPermissionManager.java:182)
  	at com.atlassian.jira.security.WorkflowBasedPermissionManager.workflowPermissionCheck(WorkflowBasedPermissionManager.java:137)
  	at com.atlassian.jira.security.WorkflowBasedPermissionManager.hasPermission(WorkflowBasedPermissionManager.java:111)
  	at com.atlassian.jira.security.DefaultPermissionManager.lambda$hasProjects$0(DefaultPermissionManager.java:266)
  	at com.atlassian.jira.security.DefaultPermissionManager$$Lambda$1334/817143143.apply(Unknown Source)
  	at com.google.common.collect.Iterators.indexOf(Iterators.java:764)
  	at com.google.common.collect.Iterators.any(Iterators.java:663)
  	at com.google.common.collect.Iterables.any(Iterables.java:608)
  	at com.atlassian.jira.security.DefaultPermissionManager.hasProjects(DefaultPermissionManager.java:266)
  

• while at the same time 1 thread is holding the lock, and also trying to write into the log files

  "http-nio-8080-exec-81 url:/login.jsp" #145984 daemon prio=5 os_prio=0 tid=0x00007f6260024000 nid=0x24c runnable [0x00007f600884c000]
     java.lang.Thread.State: RUNNABLE
  	at java.io.FileOutputStream.writeBytes(Native Method)
  	at java.io.FileOutputStream.write(FileOutputStream.java:326)
  	at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
  	at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
  	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
  	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
  	- locked <0x000000063ca28730> (a java.io.OutputStreamWriter)
  	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
  	at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
  	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
  	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 <0x00000003c14b8448> (a org.apache.log4j.RollingFileAppender)
  	at com.atlassian.jira.logging.JiraHomeAppender.doAppend(JiraHomeAppender.java:206
  

• logs will be flooded with this message (thousand times per second)

  2020-08-18 14:30:36,485 http-nio-8080-exec-30 url:/rest/api/1.0/menus/find_link username:XXXXXXXX url:/login.jsp DEBUG anonymous XXXxXXXXXXxXXX - XXXXX /login.jsp [c.a.jira.security.WorkflowBasedPermissionManager] CREATE_ISSUES permission denied by permission scheme
  

Workaround

Disable the debugging package com.atlassian.jira.security (or any sub-debugging packages of it (such as com.atlassian.jira.security.DefaultPermissionManager or com.atlassian.jira.security.WorkflowBasedPermissionManager)

Note

This type of issue is more likely to occur if Jira is writing log files on a slow hard disk, so one way to mitigate this issue would be to change the location of Jira's home folder (where the Jira application logs are stored) to a faster disk.