Search code examples
javaspringlog4j2oracle19c

Asynchronously Log4j2 JDBC Appender "Unable to write to database"


Created log4j2.xml file under src/main/resources folder as below:

    <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO" monitorInterval="30">
    <Properties>
        <Property name="log-path">logs</Property>
        <Property name="enable-jndi">true</Property>
    </Properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout
                pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        </Console>
        <JDBC name="databaseAppender" tableName="LOG_TABLE">

            <ConnectionFactory
                class="com.example.demo.ConnectionFactory"
                method="getDatabaseConnection" />
            <Column name="LOG_LEVEL" isUnicode="false" pattern="%level" />
            <Column name="CLASS_NAME" isUnicode="false" pattern="%C" />
            <Column name="METHOD_NAME" isUnicode="false" pattern="%M" />
            <Column name="LINE_NUMBER" isUnicode="false" pattern="%L" />
            <Column name="MESSAGE" isUnicode="false" pattern="%m" />
            <Column name="THREAD_NAME" isUnicode="false" pattern="%t" />
            <Column name="TIMESTAMP" isUnicode="false"
                pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}" />
        </JDBC>
        <Async name="AsyncOracle" bufferSize="262144"
            includeLocation="true">
            <AppenderRef ref="databaseAppender" />
        </Async>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console" />
            <AppenderRef ref="AsyncOracle" />
        </Root>
    </Loggers>
</Configuration>

Also created the DB connection file as:

    import java.sql.Connection;
    import java.sql.SQLException;
    
    import javax.sql.DataSource;
    
    import org.springframework.beans.factory.annotation.Value;
    import org.springframework.context.annotation.Bean;
    
    import oracle.jdbc.pool.OracleDataSource;
    
    public class ConnectionFactory {
        
        @Value("${spring.datasource.url}")
        private String url;
    
        @Value("${spring.datasource.username}")
        private String username;
    
        @Value("${spring.datasource.password}")
        private String password;
    
        @Value("${spring.datasource.driver-class-name}")
        private String driver;
        
        private static interface Singleton {
            final ConnectionFactory INSTANCE = new ConnectionFactory();
        }
    
        @Bean
        public DataSource dataSource() throws SQLException {
            OracleDataSource dataSource = new OracleDataSource();
            dataSource.setURL(url);
            dataSource.setUser(username);
            dataSource.setPassword(password);
            dataSource.setURL(url);
            dataSource.setImplicitCachingEnabled(true);
            dataSource.setFastConnectionFailoverEnabled(true);
            dataSource.setDriverType("oracle.jdbc.driver.OracleDriver");
            return dataSource();
        }
    
    
        public static Connection getDatabaseConnection() throws SQLException {
            return Singleton.INSTANCE.dataSource().getConnection();
        }
    }

application.properties file as:

    spring.datasource.url=jdbc:oracle:thin:@localhost:1521:xe
    spring.datasource.username=test
    spring.datasource.password=test
    spring.datasource.driver-class-name=oracle.jdbc.driver.OracleDriver
    
    logging.config=classpath:log4j2.xml
    Log4j2.enableJndiJdbc=true

But still facing the below error:

    2023-05-03 16:38:05,150 Log4j2-AsyncAppenderEventDispatcher-2-AsyncOracle ERROR Unable to write to database [JdbcManager{name=databaseAppender, bufferSize=0, tableName=LOG_TABLE, columnConfigs=[{ name=LOG_LEVEL, layout=%level, literal=null, timestamp=false }, { name=CLASS_NAME, layout=%C, literal=null, timestamp=false }, { name=METHOD_NAME, layout=%M, literal=null, timestamp=false }, { name=LINE_NUMBER, layout=%L, literal=null, timestamp=false }, { name=MESSAGE, layout=%m, literal=null, timestamp=false }, { name=THREAD_NAME, layout=%t, literal=null, timestamp=false }, { name=TIMESTAMP, layout=%d{yyyy-MM-dd HH:mm:ss.SSS}, literal=null, timestamp=false }], columnMappings=[]}] for appender [databaseAppender]. org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to JDBC Manager 'JdbcManager{name=databaseAppender, bufferSize=0, tableName=LOG_TABLE, columnConfigs=[{ name=LOG_LEVEL, layout=%level, literal=null, timestamp=false }, { name=CLASS_NAME, layout=%C, literal=null, timestamp=false }, { name=METHOD_NAME, layout=%M, literal=null, timestamp=false }, { name=LINE_NUMBER, layout=%L, literal=null, timestamp=false }, { name=MESSAGE, layout=%m, literal=null, timestamp=false }, { name=THREAD_NAME, layout=%t, literal=null, timestamp=false }, { name=TIMESTAMP, layout=%d{yyyy-MM-dd HH:mm:ss.SSS}, literal=null, timestamp=false }], columnMappings=[]}': JDBC connection not available [columnConfigs=[{ name=LOG_LEVEL, layout=%level, literal=null, timestamp=false }, { name=CLASS_NAME, layout=%C, literal=null, timestamp=false }, { name=METHOD_NAME, layout=%M, literal=null, timestamp=false }, { name=LINE_NUMBER, layout=%L, literal=null, timestamp=false }, { name=MESSAGE, layout=%m, literal=null, timestamp=false }, { name=THREAD_NAME, layout=%t, literal=null, timestamp=false }, { name=TIMESTAMP, layout=%d{yyyy-MM-dd HH:mm:ss.SSS}, literal=null, timestamp=false }], sqlStatement=insert into LOG_TABLE (LOG_LEVEL,CLASS_NAME,METHOD_NAME,LINE_NUMBER,MESSAGE,THREAD_NAME,TIMESTAMP) values (?,?,?,?,?,?,?), factoryData=FactoryData [connectionSource=factory{ public static java.sql.Connection com.example.demo.ConnectionFactory.getDatabaseConnection() }, tableName=LOG_TABLE, columnConfigs=[{ name=LOG_LEVEL, layout=%level, literal=null, timestamp=false }, { name=CLASS_NAME, layout=%C, literal=null, timestamp=false }, { name=METHOD_NAME, layout=%M, literal=null, timestamp=false }, { name=LINE_NUMBER, layout=%L, literal=null, timestamp=false }, { name=MESSAGE, layout=%m, literal=null, timestamp=false }, { name=THREAD_NAME, layout=%t, literal=null, timestamp=false }, { name=TIMESTAMP, layout=%d{yyyy-MM-dd HH:mm:ss.SSS}, literal=null, timestamp=false }], columnMappings=[], immediateFail=false, retry=true, reconnectIntervalMillis=5000, truncateStrings=true], connection=null, statement=null, reconnector=Reconnector [latch=java.util.concurrent.CountDownLatch@3829a5de[Count = 0], shutdown=false], isBatchSupported=false, columnMetaData=null]
        at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.checkConnection(JdbcDatabaseManager.java:507)
        at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:610)
        at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeThrough(JdbcDatabaseManager.java:888)
        at org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:264)
        at org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:110)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
        at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.dispatch(AsyncAppenderEventDispatcher.java:118)
        at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.dispatchAll(AsyncAppenderEventDispatcher.java:80)
        at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.run(AsyncAppenderEventDispatcher.java:62)

Dependencies used:

    <parent>
           <groupId>org.springframework.boot</groupId>
           <artifactId>spring-boot-starter-parent</artifactId>
           <version>2.7.11</version>
           <relativePath />
           <!-- lookup parent from repository -->
       </parent>
       <dependencies>
           <dependency>
               <groupId>org.springframework.boot</groupId>
               <artifactId>spring-boot-starter-web</artifactId>
           </dependency>
           <dependency>
               <groupId>org.springframework.boot</groupId>
               <artifactId>spring-boot-starter</artifactId>
               <exclusions>
                   <exclusion>
                       <groupId>org.springframework.boot</groupId>
                       <artifactId>spring-boot-starter-logging</artifactId>
                   </exclusion>
               </exclusions>
           </dependency>
           <dependency>
               <groupId>org.springframework.boot</groupId>
               <artifactId>spring-boot-starter-test</artifactId>
               <scope>test</scope>
           </dependency>
           <dependency>
               <groupId>com.lmax</groupId>
               <artifactId>disruptor</artifactId>
               <version>3.4.2</version>
           </dependency>
           <dependency>
               <groupId>com.oracle.database.jdbc</groupId>
               <artifactId>ojdbc8</artifactId>
               <version>19.8.0.0</version>
           </dependency>
           <dependency>
               <groupId>org.apache.logging.log4j</groupId>
               <artifactId>log4j-core</artifactId>
               <version>2.14.1</version>
           </dependency>
       </dependencies>

We are trying to persist the logging messages in database asynchronously using Log4j2, but facing issues.


Solution

  • Spring will inject the @Value annotated fields only in beans managed by Spring (it means created and destroyed by Spring). Your ConnectionFactory is not managed: you instantiate it in the static initializer of your class. Therefore all its fields have null as value and the connection fails.

    How to use the JDBC appender in Spring Boot

    Logging in a Spring Boot application is configured at least twice:

    • before the ApplicationEnvironmentPreparedEvent Spring's environment (e.g. application.properties) is not available and the native Log4j 2.x Core configuration process is used (cf. documentation). Therefore you can not use the JDBC appender in your log4j2.xml file.
    • after the event is fired a reconfiguration is triggered, which uses log4j2-spring.xml if available. In this configuration file you can use Spring's environment thanks to the Spring Lookup.

    What you are attempting to do can be done in a log4j2-spring.xml configuration file with an appender definition like this:

    <JDBC name="databaseAppender" tableName="LOG_TABLE">
      <DriverManager connectionString="${spring:spring.datasource.url}"
                     driverClassName="${spring:spring.datasource.driver-class-name}"
                     userName="${spring:spring.datasource.username}"
                     password="${spring:spring.datasource.password}"/>
      <Column name="LOG_LEVEL" isUnicode="false" pattern="%level"/>
      <Column name="CLASS_NAME" isUnicode="false" pattern="%C"/>
      <Column name="METHOD_NAME" isUnicode="false" pattern="%M"/>
      <Column name="LINE_NUMBER" isUnicode="false" pattern="%L"/>
      <Column name="MESSAGE" isUnicode="false" pattern="%m"/>
      <Column name="THREAD_NAME" isUnicode="false" pattern="%t"/>
      <Column name="TIMESTAMP" isUnicode="false" pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}"/>
    </JDBC>
    

    Dependencies configuration

    You need to upgrade log4j-core, since the version you are using has multiple security vulnerabilities.

    Spring Boot is very opinionated about artifact versions: since you are using spring-boot-starter-parent you have more than a hundred managed dependencies. IMHO the general rule about Spring Boot dependencies is:

    • don't override a version (don't provide a <version> property) if Spring Boot manages it. In your POM only disruptor is not managed by Spring Boot,
    • don't use a direct dependency if there is a starter for it. For Log4j 2.x Core Spring Boot provides spring-boot-starter-log4j2.

    Therefore your Maven dependencies should look like:

    <dependencies>
      <!-- Replace if you are using a different logging API -->
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
      </dependency>
      <!--
        ~ These are not used directly in your code, hence the `runtime` scope.
        -->
      <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-log4j2</artifactId>
        <scope>runtime</scope>
      </dependency>
      <dependency>
        <groupId>com.oracle.database.jdbc</groupId>
        <artifactId>ojdbc8</artifactId>
        <scope>runtime</scope>
      </dependency>
      <!-- Not managed by Spring Boot -->
      <!-- Version suggested by `log4j-core` 2.20.0 -->
      <dependency>
        <groupId>com.lmax</groupId>
        <artifactId>disruptor</artifactId>
        <version>3.4.4</version>
        <scope>runtime</scope>
      </dependency>
      <!-- Contains Spring Lookup -->
      <!-- Not required any more in Spring Boot 3.x -->
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-spring-boot</artifactId>
        <scope>runtime</scope>
      </dependency>
    </dependencies>
    

    Edit:

    Remark: you don't need LMAX disruptor to use asynchronous appenders. You would need it for asynchronous loggers. Asynchronous loggers give you a considerable performance bust (cf. benchmark), but asynchronous loggers + asynchronous appender will probably slow down to the performance of an asynchronous appender.