Logging not working in bahmni-erp-connect (0.93)

mdg583 · June 2, 2024, 4:28pm

I am working on a Bahmni 0.93 system, and I’ve been trying to get logging working well to make it easier to monitor and diagnose the system, in particular to diagnose issues of data passing between bahmni components. I’ve noticed that the logging in the bahmni-erp-connect service doesn’t seem to be working correctly.

After modifying the log4j2.xml file, when I run the service I get the error:

INFO: Initializing log4j from [/opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml]
Jun 02, 2024 1:17:41 PM org.apache.catalina.core.StandardContext listenerStart
SEVERE: Exception sending context initialized event to listener instance of class org.springframework.web.util.Log4jConfigListener
java.lang.NoClassDefFoundError: org/apache/log4j/xml/DOMConfigurator
	at org.springframework.util.Log4jConfigurer.initLogging(Log4jConfigurer.java:75)
	at org.springframework.web.util.Log4jWebConfigurer.initLogging(Log4jWebConfigurer.java:152)
	at org.springframework.web.util.Log4jConfigListener.contextInitialized(Log4jConfigListener.java:46)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4853)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5314)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1408)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.ClassNotFoundException: org.apache.log4j.xml.DOMConfigurator
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1333)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1167)
	... 12 more

Searching online seems to indicate that trying to load DOMConfigurator is a result of something expecting log4j version 1 rather than log4j2. (But I don’t know for sure if this is the case). I’ve carefully checked the dependencies in the source code (openerp-atomfeed-service release-0.93 branch) to try to ensure that log4j isn’t loaded but haven’t been able to find what is causing this.

I noticed that bin/start.sh runs the jar file lib/bahmni-erp-connect.jar. That jar file appears to be a packaged tomcat server. Searching in that jar file, I see the following files:

org/apache/juli/logging/DirectJDKLog.class
org/apache/juli/logging/Log.class
org/apache/juli/logging/LogConfigurationException.class
org/apache/juli/logging/LogFactory.class

I’m wondering if the logging in this jar file is what is causing the error? I have no idea if this is true. I also don’t know how to re-build and re-deploy this jar file (I have only been replacing the contents of the folder /opt/bahmni-erp-connect/bahmni-erp-connect). Potentially a solution would be for bahmni-erp-connect to be changed from using spring-webmvc to using spring-boot. I feel like I would give this a try (using something like this), but this may be attempting too much for my limited experience. I was wondering if this made any sense to others, or if others knew of a better way to fix the logging. Perhaps the only option is to first migrate to the docker-based system.

angshuonline · June 13, 2024, 11:57am

Will check on this @mdg583.

cc @deepthi @rahu1ramesh

deepthi · June 14, 2024, 10:43am

Hello @mdg583 can you please tell which version of erp-connect you are using and what changes are you trying to do to log4j2.xml file.

mdg583 · June 14, 2024, 1:09pm

bahmni-erp-connect has been installed via an rpm-based installation of Bahmni 0.93. The installed package version for bahmni-erp-connect is 0.93-82.

When bahmni-erp-connect is run, there is no log file generated (in /opt/bahmni-erp-connect/log). When I stop the service and then start it using /opt/bahmni-erp-connect/bin/bahmni-erp-connect, it writes logging information to a file called nohup.out. This file gives the following message:

Jun 14, 2024 4:02:15 PM org.apache.catalina.core.ApplicationContext log
INFO: No Spring WebApplicationInitializer types detected on classpath
Jun 14, 2024 4:02:15 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing log4j from [/opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml]
log4j:WARN Fatal parsing error 2 and column 6
log4j:WARN The processing instruction target matching "[xX][mM][lL]" is not allowed.
log4j:ERROR Could not parse url [file:/opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml].
org.xml.sax.SAXParseException; systemId: file:/opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml; lineNumber: 2; columnNumber: 6; The processing instruction target matching "[xX][mM][lL]" is n
ot allowed.
	at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(Unknown Source)
	at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(Unknown Source)
	at javax.xml.parsers.DocumentBuilder.parse(Unknown Source)
	at org.apache.log4j.xml.DOMConfigurator$2.parse(DOMConfigurator.java:612)
	at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:711)
	at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:618)
	at org.apache.log4j.xml.DOMConfigurator.configure(DOMConfigurator.java:743)
	at org.springframework.util.Log4jConfigurer.initLogging(Log4jConfigurer.java:75)
	at org.springframework.web.util.Log4jWebConfigurer.initLogging(Log4jWebConfigurer.java:152)
	at org.springframework.web.util.Log4jConfigListener.contextInitialized(Log4jConfigListener.java:46)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4853)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5314)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1408)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
Jun 14, 2024 4:02:15 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring root WebApplicationContext
log4j:WARN No appenders could be found for logger (org.springframework.web.context.ContextLoader).
log4j:WARN Please initialize the log4j system properly.
[Fatal Error] log4j2.xml:2:6: The processing instruction target matching "[xX][mM][lL]" is not allowed.
ERROR StatusLogger Error parsing /opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml
 org.xml.sax.SAXParseException; systemId: file:///opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml; lineNumber: 2; columnNumber: 6; The processing instruction target matching "[xX][mM][lL]" i
s not allowed.
	at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(Unknown Source)
	at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(Unknown Source)
	at org.apache.logging.log4j.core.config.xml.XmlConfiguration.<init>(XmlConfiguration.java:92)
	at org.apache.logging.log4j.core.config.xml.XmlConfigurationFactory.getConfiguration(XmlConfigurationFactory.java:46)
	at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:557)
	at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:481)
	at org.apache.logging.log4j.core.config.ConfigurationFactory.getConfiguration(ConfigurationFactory.java:323)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:695)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:716)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:270)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:155)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196)
	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:599)
	at org.bahmni.openerp.web.http.client.HttpClient.<clinit>(HttpClient.java:16)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
	at java.lang.reflect.Constructor.newInstance(Unknown Source)
	at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:147)
	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:122)
	at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:267)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1131)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1034)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:504)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476)
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:762)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:757)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480)
	at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:403)
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
	at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4853)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5314)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1408)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
ERROR StatusLogger No logging configuration
Jun 14, 2024 4:02:18 PM org.apache.catalina.core.ApplicationContext log

I was hoping that logging could be fixed by modifying log4j2.xml. Looking at bahmni-erp-connect/WEB-INF/classes/log4j2.xml, one issue seems to be that there is a blank line at the top:


<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/">
    <Appenders>
        <RollingFile name="fileAppender"
                     fileName="/var/log/bahmni-erp-connect/bahmni-erp-connect.log">
            <PatternLayout pattern="%d %-5p [openerp-atomfeed-service] [%c] %m%n"/>
            <Policies>
                <SizeBasedTriggeringPolicy size="10MB"/>
            </Policies>
            <DefaultRolloverStrategy max="10"/>
        </RollingFile>
    </Appenders>

    <Loggers>
        <Logger name="org.springframework" level ="WARN"/>
    </Loggers>
    <Root level="WARN">
        <AppenderRef ref="fileAppender" />
    </Root>
</Configuration>

After removing the line and restarting, the console output in nohup.out shows:

Jun 14, 2024 4:07:01 PM org.apache.catalina.core.ApplicationContext log
INFO: No Spring WebApplicationInitializer types detected on classpath
Jun 14, 2024 4:07:01 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing log4j from [/opt/bahmni-erp-connect/bahmni-erp-connect/WEB-INF/classes/log4j2.xml]
log4j:WARN Continuable parsing error 2 and column 61
log4j:WARN Document root element "Configuration", must match DOCTYPE root "null".
log4j:WARN Continuable parsing error 2 and column 61
log4j:WARN Document is invalid: no grammar found.
log4j:ERROR DOM element is - not a <log4j:configuration> element.
Jun 14, 2024 4:07:01 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring root WebApplicationContext
log4j:WARN No appenders could be found for logger (org.springframework.web.context.ContextLoader).
log4j:WARN Please initialize the log4j system properly.
2024-06-14 16:07:03,332 localhost-startStop-1 ERROR The parameter is null: filePattern
2024-06-14 16:07:03,341 localhost-startStop-1 ERROR Could not create plugin of type class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile org.apache.logging.log4j.core.config.C
onfigurationException: Arguments given for element RollingFile are invalid: field 'filePattern' has invalid value 'null'
	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.injectFields(PluginBuilder.java:210)
	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:121)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1120)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1045)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1037)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:651)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:247)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:293)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:626)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:699)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:716)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:270)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:155)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196)
	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:599)
	at org.bahmni.openerp.web.http.client.HttpClient.<clinit>(HttpClient.java:16)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
	at java.lang.reflect.Constructor.newInstance(Unknown Source)
	at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:147)
	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:122)
	at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:267)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1131)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1034)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:504)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476)
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:762)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:757)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480)
	at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:403)
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
	at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4853)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5314)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1408)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)

2024-06-14 16:07:03,343 localhost-startStop-1 ERROR Null object returned for RollingFile in Appenders.
2024-06-14 16:07:03,349 localhost-startStop-1 ERROR Unknown object "Root" of type org.apache.logging.log4j.core.config.LoggerConfig is ignored: try nesting it inside one of: ["Appenders", "Loggers", "Properties"
, "Scripts", "CustomLevels"].
Jun 14, 2024 4:07:03 PM org.apache.catalina.core.ApplicationContext log

That is about as far as I got. I thought that maybe something is expecting a different log4j configuration format, maybe for log4j version 1