Syntax highlighter header

Saturday, 5 September 2020

Configuring Log4j 2

In this post I am going to explain configuring Log4J 2 to log high severity log messages to console and file both and lower severity messages only to log file. This way console is not cluttered with unnecessary messages and detail information is available for debugging in log file.

I will define two appenders A and R. The appender A has a threshold filter applied to it which accepts only log messages with severity level ERROR and higher. The appender R don't have any filter attached to it, so it will log all messages.

The location of log4j2.xml need to be provided using system property log4j.configurationFile, for example -Dlog4j.configurationFile=/my/path/log4j2.xml

 Please note that system property log4j.configuration is used for Log4J 1.2 which has different syntax.



<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
        <Appenders>
                <Console name="A" target="SYSTEM_OUT">
                        <PatternLayout pattern="%d [%t] %-5p {%F:%L} %x - %m%n" />
                        <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
                </Console>

                <RollingFile name="R"
                        fileName="/home/tomcat/logs/tomcat-log4j2.log" filePattern="/home/tomcat/logs/tomcat-log4j2-%d{yyyy-MM-dd}.log">
                        <PatternLayout pattern="%d [%t] %-5p {%F:%L} %x - %m%n" />
                        <Policies>
                                <TimeBasedTriggeringPolicy interval="1" />
                        </Policies>
                </RollingFile>
        </Appenders>


        <Loggers>
                <Logger name="org.apache" level="trace"/>
                <Root level="ERROR">
                        <AppenderRef ref="A" />
                        <AppenderRef ref="R" />
                </Root>
        </Loggers>
</Configuration>

Configuring Log4j 1.2

Log4j 1.2 is deprecated version of Log4J but it is still used extensively. It is default implementation apache commons-logging. I am going to explain configuration of log4j 1.2 in this post.

My aim it to log all message with log level ERROR and higher to log file and console both and messages with  level TRACE and higher to log file. This way console will receive higher priority messages and more detailed logs will be logged to the log file.

To achieve this I create two appenders A and R. A is console appender. I will set threshold of appender A to ERROR so any message lower than ERROR will not be logged with this appender. Appender R logs to tomcat.log and it does not have any threshold attached to it.

The location for log4.properties need to be specified using system property log4j.configuration. For example -Dlog4j.configuration=/my/path/log4j.properties 

Please note that log4j.configurationFile system property is used by Log4J 2 which has a different syntax.


log4j.rootLogger=ERROR,A,R
#*** A is the console appender
log4j.appender.A=org.apache.log4j.ConsoleAppender
#*** A uses pattern layout
log4j.appender.A.layout=org.apache.log4j.PatternLayout
log4j.appender.A.threshold=ERROR
log4j.appender.A.layout.ConversionPattern=%d [%t] %-5p {%F:%L} %x - %m%n

#**** R is the Rolling FileAppender
log4j.appender.R=org.apache.log4j.DailyRollingFileAppender
log4j.appender.R.File=/home/tomcat/logs/tomcat.log
log4j.appender.R.DatePattern='.'yyyy-MM-dd
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d [%t] %-5p {%F:%L} %x - %m%n

#*** Log Levels
log4j.logger.org.apache=TRACE

Saturday, 29 August 2020

Fixing EJB error in Wildfly 20

 Recently I was working on porting my company application to wildfly. We were stuck at an EJB exception when we tried to access any EJB method. We were accessing EJB from Wildfly application itself.


2020-08-29 13:26:20,833 [ServerService Thread Pool -- 102] ERROR {DataUpdaterImpl.java:1903} [] - EJBCLIENT000079: Unable to discover destination for request for EJB StatelessEJBLocator for "A/B/TestEJB", view is interface com.A.B.Test, affinity is None
javax.ejb.NoSuchEJBException: EJBCLIENT000079: Unable to discover destination for request for EJB StatelessEJBLocator for "ctools/ctservices/UniqueIdGeneratorEJB", view is interface com.tk20.ejb.api.util.UniqueIdGenerator, affinity is None
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:622) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:553) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.protocol.remote.RemotingEJBClientInterceptor.handleInvocationResult(RemotingEJBClientInterceptor.java:57) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:624) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:553) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.TransactionPostDiscoveryInterceptor.handleInvocationResult(TransactionPostDiscoveryInterceptor.java:148) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:624) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:553) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.DiscoveryEJBClientInterceptor.handleInvocationResult(DiscoveryEJBClientInterceptor.java:137) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:624) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:553) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.NamingEJBClientInterceptor.handleInvocationResult(NamingEJBClientInterceptor.java:87) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:624) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:553) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.TransactionInterceptor.handleInvocationResult(TransactionInterceptor.java:212) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:624) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:553) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBClientInvocationContext.awaitResponse(EJBClientInvocationContext.java:995) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:191) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:125) ~[jboss-ejb-client-4.0.33.Final.jar!/:4.0.33.Final]
        at com.sun.proxy.$Proxy124.getUniqueIdString(Unknown Source) ~[?:?]


This error took a lot of time to fix. There was no information available on internet. The problem is the way JNDI lookup is done. We were looking up "ejb:A/B/TestEJB" in JNDI. The lookup was successful but method invocation failed. The problem was fixed after changing the JNDI lookup to "java:global/A/B/Test".

The remote lookup for "java:global/A/B/Test" in JNDI failed. So for remote invocation the JNDI lookup have to be done without any qualifier that is "/A/B/Test". After doing this remote EJB calls also started working fine.

The local lookup and remote lookup need to be done differently.

Please refer to following post for accessing EJBs from remote machine.

https://blog.bigdatawithjasvant.com/2021/06/fixing-jboss-local-user.html

Monday, 20 July 2020

Tuning ThreadPoolExecutor and BlockingQueueSize

ThreadPoolExecutor uses a blocking queue for storing requests till some executor thread is available to execute the request. But if request are arriving at a rate higher than the rate at which requests are getting processed then this queue will keep growing and ultimately will lead to OutOfMemoryError and application with fail.

Solution to this problem is to use a bounded queue with fixed size and reject requests when queue is full. The problem is to find optimum size of the queue so that it can be sufficient to buffer the busts in requests and not too big to fail the system or provide late response which is as good as failure.

I conducted a small experiment using the following code to find out optimum queue size for ThreadPoolExecutor. This code uses a SynchronusQueue which has a queue size 0. This code stabilizes at 18 worker threads. When I use a Linked blocking Queue with size 10 this code stabalizes a 13 worker threads and stable queue size being 0 or 1 items in queue. When number of worker threads were 10 then the queue size increased to 10 and that lead to increase in worker threads but once worker threads were increased to 13 the requirement of queue size decreased. With queue size of 20 also thread pool stabilized at 13 worker threads. 13 worker threads were needed for processing average work load so increasing queue size to 20 did not help and was filled up eventually. Queue size of 10 was good enough. 

My recommendation is to keep the queue size equal to number of core threads.


package test;

import java.util.concurrent.BlockingQueue;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.SynchronousQueue;
import java.util.concurrent.ThreadLocalRandom;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;

public class ThreadPoolTest {
 
 public static class Producer implements Runnable {
  ThreadPoolExecutor threadPool;
  public Producer(ThreadPoolExecutor es) {
   threadPool =es;
  }

  @Override
  public void run() {
   for(int i=0; i<180; i++) {
    int delay = ThreadLocalRandom.current().nextInt(2000);
    try {
     Thread.sleep(delay);
    } catch (InterruptedException e) {
     
    }
    threadPool.execute(new Task());
    int queueSize = threadPool.getQueue().size();
    int poolSize = threadPool.getPoolSize();
    System.out.println("Submitted task, queueSize="+ queueSize +" poolSize="+ poolSize);
   }   
  }
  
 }
 
 public static class Task implements Runnable{

  @Override
  public void run() {
   int delay = ThreadLocalRandom.current().nextInt(2000);
   try {
    Thread.sleep(delay);
   } catch (InterruptedException e) {
    return;
   }   
  }
  
 }

 public static void main(String[] args) {
  BlockingQueue bq = new SynchronousQueue<>();
  ThreadPoolExecutor tp = new ThreadPoolExecutor(10, 20, 2, TimeUnit.MINUTES,bq);
  for(int i=0; i<10; i++) {
   new Thread(new Producer(tp)).start();   
  }

 }

}

java.lang.OutOfMemoryError: Unable to create new native thread

Recently I received the error "java.lang.OutOfMemoryError: Unable to create new native thread" and when we debugged the issue on the linux machine the root cause was not related to memory but something totally different.  In Java when OS denies to create more threads because limit of number of processes have hit the limit then this error get mapped to java.lang.OutOfMemoryError because there is no specific error defined in java for capturing denial of creation of new thread due to hitting limit of number of processes.

If you want to check limits on a linux machine then you need to run the following command:

$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 62837
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 16384
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 10240
cpu time               (seconds, -t) unlimited
max user processes              (-u) 1024
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited


"max user process" define maximum number of child processes/threads a root level unix process can open. There are soft limits and hard limits, soft limits can be set on a process and it applicable to that process and child processes and hard limit is applicable to all processes of that user.

In our case soft limit was configured to 1024 and we were trying to create more number of threads.
The limit is defined in file "/etc/security/limits.d/90-nproc.conf" we changed number of processes to 2048 and our application started working. 


# Default limit for number of user's processes to prevent
# accidental fork bombs.
# See rhbz #432903 for reasoning.

*          soft    nproc     1024
root       soft    nproc     unlimited

In Java denial of any resource by OS to application maps to java.lang.OutOfMemoryError and real reason might not be related to memory.