1

I'm trying to upgrade as detailed above. Going from Log4J 2.11.0 to 2.17.1 completely breaks my runtime Log4J database appender setup, breaking in the underlying MariaDB JDBC driver when trying to write log entries to Percona 5.7 / MySQL 5.7.

2.11.0 is working fine and has been for a very, very long time in this app.

Trying to log to Percona 5.7 (MySQL 5.7) via the MariaDB JDBC driver.

Changed my pom.xml for Log4J2 from

       <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <version>2.11.0</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <version>2.11.0</version>
        </dependency>

to

       <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <version>2.17.1</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <version>2.17.1</version>
        </dependency>

My log4j2.xml (working fine with 2.11.0 - must it be changed for 2.17.1?):

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5p %c{1} - %m %n" />
        </Console> 
        <File name="MyFile" fileName="my.log" immediateFlush="true" append="true">
            <PatternLayout pattern=" %d{yyyy-MM-dd HH:mm:ss.SSS} %-5p %c{1} - %m %n"/>
        </File>
        <JDBC name="MyDB" tableName="db.log">
            <ConnectionFactory class="log4J2.utils.Log4J2GetConnection" method="getDatabaseConnection"/>
            <Column name="DATED" isEventTimestamp="true" isUnicode="false"/>            
            <Column name="LOGGER" pattern="%logger" isUnicode="false"/>
            <Column name="LEVEL" pattern="%level" isUnicode="false"/>
            <Column name="MESSAGE" pattern="%message" isUnicode="false"/>
            <Column name="THROWABLE" pattern="%ex{full}" isUnicode="false" />
        </JDBC>                       
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console" />
            <!--<AppenderRef ref="MyFile"/>-->
            <AppenderRef ref="MyDB"/>
        </Root>
    </Loggers>
</Configuration>

My connection factory:

package log4J2.utils;

import java.sql.Connection;
import java.sql.SQLException;
import java.util.Properties;
import javax.sql.DataSource;
import org.apache.commons.dbcp.DriverManagerConnectionFactory;
import org.apache.commons.dbcp.PoolableConnectionFactory;
import org.apache.commons.dbcp.PoolingDataSource;
import org.apache.commons.pool.impl.GenericObjectPool;
import AppSettings;

/**
 *
 * @author sv
 */
public class Log4J2GetConnection {

    private static interface Singleton {

        final Log4J2GetConnection INSTANCE = new Log4J2GetConnection();
    }

    private final DataSource dataSource;

    private Log4J2GetConnection() {
        if (AppSettings.getMySQLDataSource() == null) {
            AppSettings.resetMySQLDataSource();
        }

        Properties properties = new Properties();
        properties.setProperty("user", AppSettings.getMysqlUser());
        properties.setProperty("password", AppSettings.getMysqlPassword());

        String connectionString = "jdbc:mariadb://" + AppSettings.getMysqlServer() + ":" + AppSettings.getMysqlPort() + "/" + AppSettings.getMysqlDatabase();

        GenericObjectPool pool = new GenericObjectPool();
        DriverManagerConnectionFactory connectionFactory = new DriverManagerConnectionFactory(connectionString, properties);
        new PoolableConnectionFactory(connectionFactory, pool, null, "SELECT 1", 3, false, false, Connection.TRANSACTION_READ_COMMITTED);

        this.dataSource = new PoolingDataSource(pool);
    }

    public static Connection getDatabaseConnection() throws SQLException {
        return Singleton.INSTANCE.dataSource.getConnection();
    }
}

Recompiled fine.

Whenever I now try to make a log entry under 2.17.1, I get an exception as detailed below. Does not happen with 2.11.0, only with 2.17.1:

2022-01-18 10:16:31,243 main ERROR Unable to write to database [JdbcManager{name=MyDB, bufferSize=0, tableName=db.log, columnConfigs=[{ name=DATED, layout=null, literal=null, timestamp=true }, { name=LOGGER, layout=%logger, literal=null, timestamp=false }, { name=LEVEL, layout=%level, literal=null, timestamp=false }, { name=MESSAGE, layout=%message, literal=null, timestamp=false }, { name=THROWABLE, layout=%ex{full}, literal=null, timestamp=false }], columnMappings=[]}] for appender [MyDB]. org.apache.logging.log4j.core.appender.db.DbAppenderLoggingException: Failed to insert record for log event in JDBC manager: java.sql.SQLException: Malformed communication packet. [columnConfigs=[{ name=DATED, layout=null, literal=null, timestamp=true }, { name=LOGGER, layout=%logger, literal=null, timestamp=false }, { name=LEVEL, layout=%level, literal=null, timestamp=false }, { name=MESSAGE, layout=%message, literal=null, timestamp=false }, { name=THROWABLE, layout=%ex{full}, literal=null, timestamp=false }], sqlStatement=insert into asteriskcdrdb.application_log (DATED,LOGGER,LEVEL,MESSAGE,THROWABLE) values (?,?,?,?,?), factoryData=FactoryData [connectionSource=factory{ public static java.sql.Connection log4J2.utils.Log4J2GetConnection.getDatabaseConnection() }, tableName=asteriskcdrdb.application_log, columnConfigs=[{ name=DATED, layout=null, literal=null, timestamp=true }, { name=LOGGER, layout=%logger, literal=null, timestamp=false }, { name=LEVEL, layout=%level, literal=null, timestamp=false }, { name=MESSAGE, layout=%message, literal=null, timestamp=false }, { name=THROWABLE, layout=%ex{full}, literal=null, timestamp=false }], columnMappings=[], immediateFail=false, retry=true, reconnectIntervalMillis=5000, truncateStrings=true], connection=jdbc:mysql://172.16.1.13:3306/asteriskcdrdb, UserName=asteriskcdruser, mariadb-jdbc, statement=sql : 'insert into asteriskcdrdb.application_log (DATED,LOGGER,LEVEL,MESSAGE,THROWABLE) values (?,?,?,?,?)', parameters : ['2022-01-18 10:15:59.319','webServer.WebHost','INFO','1iemp3w272hi - WebHost class - Starting jetty...',''], reconnector=null, isBatchSupported=true, columnMetaData={MESSAGE=ColumnMetaData [schemaName=, catalogName=asteriskcdrdb, tableName=application_log, name=MESSAGE, nameKey=MESSAGE, label=MESSAGE, displaySize=65535, type=12, typeName=VARCHAR, className=java.lang.String, precision=196605, scale=0, isStringType=true], LOGGER=ColumnMetaData [schemaName=, catalogName=asteriskcdrdb, tableName=application_log, name=LOGGER, nameKey=LOGGER, label=LOGGER, displaySize=255, type=12, typeName=VARCHAR, className=java.lang.String, precision=765, scale=0, isStringType=true], DATED=ColumnMetaData [schemaName=, catalogName=asteriskcdrdb, tableName=application_log, name=DATED, nameKey=DATED, label=DATED, displaySize=19, type=93, typeName=DATETIME, className=java.sql.Timestamp, precision=19, scale=0, isStringType=false], LEVEL=ColumnMetaData [schemaName=, catalogName=asteriskcdrdb, tableName=application_log, name=LEVEL, nameKey=LEVEL, label=LEVEL, displaySize=10, type=12, typeName=VARCHAR, className=java.lang.String, precision=30, scale=0, isStringType=true], THROWABLE=ColumnMetaData [schemaName=, catalogName=asteriskcdrdb, tableName=application_log, name=THROWABLE, nameKey=THROWABLE, label=THROWABLE, displaySize=65535, type=12, typeName=VARCHAR, className=java.lang.String, precision=196605, scale=0, isStringType=true]}]
    at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeInternal(JdbcDatabaseManager.java:871)
    at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeThrough(JdbcDatabaseManager.java:898)
    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:161)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:542)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:500)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
    at org.apache.logging.log4j.core.Logger.log(Logger.java:161)
    at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2017)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1983)
    at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1320)
    at webServer.WebHost.<init>(WebHost.java:58)
    at App.main(App.java:255)
Caused by: java.sql.SQLException: Malformed communication packet.
    at org.mariadb.jdbc.internal.SQLExceptionMapper.get(SQLExceptionMapper.java:149)
    at org.mariadb.jdbc.internal.SQLExceptionMapper.throwException(SQLExceptionMapper.java:106)
    at org.mariadb.jdbc.MySQLStatement.executeQueryEpilog(MySQLStatement.java:268)
    at org.mariadb.jdbc.MySQLStatement.execute(MySQLStatement.java:296)
    at org.mariadb.jdbc.MySQLStatement.executeUpdate(MySQLStatement.java:325)
    at org.mariadb.jdbc.MySQLPreparedStatement.executeUpdate(MySQLPreparedStatement.java:159)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
    at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeInternal(JdbcDatabaseManager.java:862)
    ... 21 more
Caused by: org.mariadb.jdbc.internal.common.QueryException: Malformed communication packet.
    at org.mariadb.jdbc.internal.mysql.MySQLProtocol.getResult(MySQLProtocol.java:982)
    at org.mariadb.jdbc.internal.mysql.MySQLProtocol.executeQuery(MySQLProtocol.java:1042)
    at org.mariadb.jdbc.MySQLStatement.execute(MySQLStatement.java:289)
    ... 26 more

My MariaDB JDBC artifact in my pom.xml:

        <dependency>
            <groupId>org.mariadb.jdbc</groupId>
            <artifactId>mariadb-java-client</artifactId>
            <version>1.1.8</version>
        </dependency>

E. g. all logging attempts by version 2.17.1 of Log4J fail in Percona 5.7 with the error in the MariaDB JDBC driver of

org.apache.logging.log4j.core.appender.db.DbAppenderLoggingException: Failed to insert record for log event in JDBC manager: java.sql.SQLException: Malformed communication packet.

The moment I switch back in the pom.xml to Log4J 2.11.0, the communication packets emitted by the MariaDB JDBC driver to Percona 5.7 are no longer considered "malformed".

Somehow Log4J 2.17.1 is affecting the MariaDB JDBC driver 1.1.8 in such a way that my Percona 5.7 instance rejects all SQL communication packets it receives from the JDBC driver, if the origin of said SQL insert query is Log4J 2.17.1... WTF

If the origin of the SQL query is no longer Log4J 2.17.1 but 2.11.0, the communication packages are no longer malformed according to Percona 5.7 and it happily executes the log insert query sent via the MariaDB JDBC driver from Log4J 2.11.0.

Any pointers as to how to fix this issue?

Thanks!

Stefan

Stefan
  • 316
  • 2
  • 16

2 Answers2

1

The solution to the above post seems to be to first update the MariaDB JDBC Java client to the current stable version. In the pom.xml for Maven:

        <dependency>
            <groupId>org.mariadb.jdbc</groupId>
            <artifactId>mariadb-java-client</artifactId>
            <!--<version>1.1.8</version>-->
            <version>2.7.4</version>
        </dependency>

2.7.4 of the MariaDB-java-client is stable as of 2022-01-18.

Then add commons-dbcp version 1.4 to allow my connection factory code to work correctly. In the pom.xml:

        <dependency>
            <groupId>commons-dbcp</groupId>
            <artifactId>commons-dbcp</artifactId>
            <version>1.4</version>
            <type>jar</type>
        </dependency>

Then finally take log4j 2.11.0 up to 2.17.1. In the pom.xml:

        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <!--<version>2.11.0</version>-->
            <version>2.17.1</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <!--<version>2.11.0</version>-->
            <version>2.17.1</version>
        </dependency>

After doing the above the exception of

db.DbAppenderLoggingException: Failed to insert record for log event in JDBC manager: java.sql.SQLException: Malformed communication packet.

was gone and Log4J 2.17.1 is now successfully logging via the MariaDb Java client 2.7.4 to Percona (MySQL) 5.7 with commons-dbcp 1.4 to make the above Log4J connection factory code work.

--

EDIT: here is an alternative connection factory class for using Apache DBCP2 instead of DBCP1 to get a connection for Log4J2 via MariaDB Java client 2.7.4 to Percona 5.7:

package verishare.log4J2.utils;

import java.sql.Connection;
import java.sql.SQLException;
import javax.sql.DataSource;
import org.apache.commons.dbcp2.PoolableConnection;
import org.apache.commons.pool2.ObjectPool;
import AppSettings;

/**
 *
 * @author sv
 */
public class Log4J2GetConnection {

    private static interface Singleton {

        final Log4J2GetConnection INSTANCE = new Log4J2GetConnection();
    }

    private final DataSource dataSource;

    private Log4J2GetConnection() {
        if (AppSettings.getMySQLDataSource() == null) {
            AppSettings.resetMySQLDataSource();
        }

        String connectionString = "jdbc:mariadb://" + AppSettings.getMysqlServer() + ":" + AppSettings.getMysqlPort() + "/" + AppSettings.getMysqlDatabase();

        org.apache.commons.dbcp2.PoolingDataSource<PoolableConnection> workDataSource = null;

        try {
            org.apache.commons.dbcp2.ConnectionFactory factory = new org.apache.commons.dbcp2.DriverManagerConnectionFactory(connectionString,
                    AppSettings.getMysqlUser(), AppSettings.getMysqlPassword());
            org.apache.commons.dbcp2.PoolableConnectionFactory poolFactory = new org.apache.commons.dbcp2.PoolableConnectionFactory(factory, null);
            ObjectPool<PoolableConnection> connectionPool = new org.apache.commons.pool2.impl.GenericObjectPool<>(poolFactory);
            poolFactory.setPool(connectionPool);
            workDataSource = new org.apache.commons.dbcp2.PoolingDataSource<>(connectionPool);
        } catch (Exception ex) {
            System.out.println(("Exception in getPoolForConnection:" + ex.toString()));
        } finally {
            this.dataSource = workDataSource;
        }
    }

    public static Connection getDatabaseConnection() throws SQLException {
        return Singleton.INSTANCE.dataSource.getConnection();
    }
}
Stefan
  • 316
  • 2
  • 16
1

FYI, Log4J vulnerability starts from 2.12.0

myJim
  • 26
  • 1