Setting Async Log4j2 is non MSR IS

vikasgre988 · March 8, 2024, 4:19am

Product/components used and version/fix level:

webMethods 10.15

Detailed explanation of the problem:

I’m working on log4j2 framework using AsyncLogger and the package is loaded with disruptor jar. The setup is working fine in MSR.

But the same setup is not working non-MSR, I did change below parameters in custom_wrapper.cnf. The log4j2 load is failing with “lmax” class not found. Not sure how to load the disruptor jar file at startup time. please help me on this.

wrapper.java.additional.204=-Dlog4j.configurationFile=“C:\SoftwareAG\profiles\IS_default/configuration/logging/log4j2.properties,.tc.custom.log4j2.properties,C:\SoftwareAG\IntegrationServer\instances\default\configuration\log4j2.xml”

wrapper.java.additional.303=-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

I removed the below 303 value from customer_wrapper.cnf to make it as Async. Is it correct? Because if I maintain the below values, then it will not work as Asynchronous

wrapper.java.additional.303=-DLog4jContextSelector=org.apache.logging.log4j.core.selector.BasicContextSelector

Error messages / full error message screenshot / log file:

INFO | jvm 1 | 2024/03/07 23:06:15 | !ENTRY com.softwareag.platform.config.store.jaas 4 0 2024-03-07 23:06:15.695
INFO | jvm 1 | 2024/03/07 23:06:15 | !MESSAGE FrameworkEvent ERROR
INFO | jvm 1 | 2024/03/07 23:06:15 | !STACK 0
INFO | jvm 1 | 2024/03/07 23:06:15 | org.osgi.framework.BundleException: Exception in com.softwareag.platform.config.store.jaas.internal.Activator.start() of bundle com.softwareag.platform.config.store.jaas.
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:836)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:765)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1022)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:363)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.Module.doStart(Module.java:589)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.Module.start(Module.java:457)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1784)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1764)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1726)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1657)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1558)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:233)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:343)
INFO | jvm 1 | 2024/03/07 23:06:15 | Caused by: java.lang.NoClassDefFoundError: com/lmax/disruptor/EventTranslatorVararg
INFO | jvm 1 | 2024/03/07 23:06:15 | at java.base/java.lang.ClassLoader.defineClass1(Native Method)
INFO | jvm 1 | 2024/03/07 23:06:15 | at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.ModuleClassLoader.defineClass(ModuleClassLoader.java:286)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.defineClass(ClasspathManager.java:716)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findClassImpl(ClasspathManager.java:639)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClassImpl(ClasspathManager.java:607)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClassImpl(ClasspathManager.java:587)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:566)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:338)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:395)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:473)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:422)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:414)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)
INFO | jvm 1 | 2024/03/07 23:06:15 | at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.createContext(AsyncLoggerContextSelector.java:46)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:218)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:136)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:123)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:117)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:150)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:137)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:55)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:47)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:33)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:363)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:388)
INFO | jvm 1 | 2024/03/07 23:06:15 | at com.softwareag.platform.config.store.jaas.internal.ConfigurationStoreImpl.(ConfigurationStoreImpl.java:44)
INFO | jvm 1 | 2024/03/07 23:06:15 | at com.softwareag.platform.config.store.jaas.internal.Activator.start(Activator.java:24)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:815)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:808)
INFO | jvm 1 | 2024/03/07 23:06:15 | at java.base/java.security.AccessController.doPrivileged(Native Method)
INFO | jvm 1 | 2024/03/07 23:06:15 | at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:808)
INFO | jvm 1 | 2024/03/07 23:06:15 | … 12 more

vikasgre988 · March 8, 2024, 1:54pm

@Senthilkumar_G , Kindly let me know if you have any insights on this issue? I followed all the ways in the issue topic Use log4j2 in webmethods - #6 by Senthil.

But for Synchronous this is fine, but in my case it is asynchronous and need to use
DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

Which is not working , as it is expecting lmax methods at the startup time

rupinder1 · March 9, 2024, 2:14pm

Can you share a screenshot of the listing of your code/classes and code/jars folders?

vikasgre988 · March 9, 2024, 2:35pm

Hi Rupinder,

Please find the snippet of code and also the jar file where we are setting the property to Async.
Also PFA for the custom_wrapper and wrapper.log file for more details.

custom_wrapper.conf (2.4 KB)
wrapper.log (468.3 KB)

Snippet of the async jar which will set the property.

Thanks,
Vikas

vikasgre988 · March 12, 2024, 1:25pm

Hi All,

Please let me know if any thoughts on this?

Thanks,
Vikas

jahntech.cj · March 13, 2024, 8:43am

What is the business requirement here?

I am asking because, depending on the use-case, there may be a much simpler solution.

vikasgre988 · March 13, 2024, 12:08pm

Hi @jahntech.cj ,

Currently we are using log4j2 with synchronous logger and working fine. But during the load test, we could see the threads related to log the data is taking time and which is directly causing delay in executing the interface related flow services.

So planning to use async logger to see whether it will increase the performance. Due to other limitations and time constraints cannot use UM, and would like to use log4j2 async logger capability here.

Thanks,
Vikas

jahntech.cj · March 13, 2024, 2:41pm

Thanks for the feedback.

Two thoughts come to mind here:

Please check if what you are planning to do will impact the support status of your installation. There is a good chance that working on this level might impact existing code. That would mean an unsupported system and I assume you don’t want that.
I must admit that I am surprised that synchronous logging does not work in terms of performance. In general it is able to reach a throughput that is way above what I have seen in even the most demanding scenarios on the IS side. To be clear: I do not doubt you having issues. But some number would be helpful to narrow things down.

Last, perhaps it can help to have a look at this GitHub project. It demoes an approach to load a particular log4j2 config file without having to play around with System properties.

vikasgre988 · March 14, 2024, 1:17pm

Thanks @jahntech.cj .

Just to clear on point 1. Do you mean it should not affect product behavior overall? If so, yes it will impact if change below context selector to async. So, it looks like non MSR not supporting this.

wrapper.java.additional.303=-DLog4jContextSelector=org.apache.logging.log4j.core.selector.BasicContextSelector

For point 2, I see similar issue in my previous projects too. But there we had MSR and handled it with different way .

I will also raise a SR and see what SAG says. Parallel I’m working on few changes in code too.

Yes , I refered the above repo too

Thanks,
Vikas

rupinder1 · March 14, 2024, 11:49pm

There is definitely some difference between MST and IS on Log4J behavior. I had written some custom logging in my package using Log4J and worked with MSR but not IS. So the support ticket may give you some ideas on what to do. In my case, I had noticed that my loggers were not working because the IS takes over all logging irrespective of what you are trying to do.

vikasgre988 · March 15, 2024, 5:41pm

Thanks @rupinder1 .

Right the custom_wrapper is not helping in this case. And IS default logger always taking precedence.

Sure, I will work with SAG over ticket and let know everyone here if I get any solutions.

Thanks,
Vikas

Senthilkumar_G · March 26, 2024, 9:23am

@vikasgre988 @rupinder1
In Integration server normal instance, not the MSR version, used the log4jv2 property to control which specific logger preferred to be asynchronous.

In the log4j.properties file,

Blockquote
##JMSlog
log4j.logger.JMS=INFO,JMSFileAppender
##Async Appender
log4j.appender.asyncLog=org.apache.log4j.AsyncAppender
log4j.appender.asyncLog.BufferSize=128
log4j.appender.asyncLog.Blocking=true
log4j.appender.asyncLog.appender-ref=JMSFileAppender

When I have multiple loggers, can specify which one to be async with comma separated

log4j.appender.asyncLog.appender-ref=JMSFileAppender, ISCustomAuditAppender

vikasgre988 · March 26, 2024, 5:55pm

Hi @Senthilkumar_G .

Right, that I’m doing in Log4j2. But to work it as Asynchronous, meaning we have to set the
DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector in custom_wrapper.

Else it will start picking with same basic context which is synchronous.
wrapper.java.additional.303=-DLog4jContextSelector=org.apache.logging.log4j.core.selector.BasicContextSelector.

in Non-MSR changing this context selector in custom_wrapper not working. And if I set it in my java service and load it as jar, still same where it take Basic Context selector from custom_wrapper.

So, updating only in Lof4j2 filw with AsyncLogger will not help, but need to set the Context Slector too.

vikasgre988 · April 10, 2024, 8:41pm

Support team mentioned that, we need to add our custom log4j config file in

wrapper.java.additional.204=-Dlog4j.configurationFile under custom wrapper.

Also, in wrapper.cnf, we need to add path of disruptor jar . set.JAVA_BOOT_CLASSPATH