You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Gary Gregory (JIRA)" <ji...@apache.org> on 2019/08/06 00:00:00 UTC
[jira] [Comment Edited] (LOG4J2-2667) "Values not bound to
statement" when using JDBC appender
[ https://issues.apache.org/jira/browse/LOG4J2-2667?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16900356#comment-16900356 ]
Gary Gregory edited comment on LOG4J2-2667 at 8/5/19 11:59 PM:
---------------------------------------------------------------
[~epmchui],
Thank you for attaching a project to reproduce the issue.
The first problem is that your configuration uses a class that does not exist: {{java.sql.Types.TIMESTAMP}}. You must have meant {{java.sql.Timestamp}}.
Beyond that, this could be a bug in the SQLite JDBC Driver:
- When an event comes in the JDBC appender, we call JDBC's {{PreparedStatement#set}} for each configured column.
- Then we call JDBC's {{PreparedStatement#addBatch()}} build a list of {{INSERT}} statements to send to the database.
- We do this for each event that comes in until a threshold is met and the whole batch is sent to the database in one go. Buy, it looks like we do not really make good use of batching since all of our batches seem to be of size one, nevertheless we use the batch API.
The appender only uses batching if the driver says it supports it, which this SQLite driver says it does. But, when the appender calls {{PreparedStatement#clearParameters()}} on this driver, there is a mismatch in expectations in how the SQLite bit field {{paramValid}} is used in the driver which causes the exception you describe.
I tried using the latest version of the JDBC Driver (3.28.0) but that does not help.
The only thing I can think to do on the Log4j side is to add a setting to forcibly disable batching even when the driver says it supports it. This would cause the appender to immediately execute SQL INSERT statements instead of batching them.
Any thoughts from the community?
was (Author: garydgregory):
[~epmchui],
Thank you for attaching a project to reproduce the issue.
The first problem is that your configuration uses a class that does not exist: {{java.sql.Types.TIMESTAMP}}. You must have meant {{java.sql.Timestamp}}.
Beyond that, this could be a bug in the SQLite JDBC Driver:
- When an event comes in the JDBC appender, we call JDBC's {{PreparedStatement#set}} for each configured column.
- Then we call JDBC's {{PreparedStatement#addBatch()}} build a list of {{INSERT}} statements to send to the database.
- We do this for each event that comes in until a threshold is met and the whole batch is sent to the database in one go. Buy, it looks like we do not really make good use of batching since all of our batches seem to be of size one, nevertheless we use the batch API.
The appender only uses batching if the driver says it supports it, which this SQLite driver says it does. But, when the appender calls {{PreparedStatement#clearParameters()}} on this driver, there is a mismatch in expectations in how the SQLite bit field {{paramValid}} is used in the driver which causes the exception you describe.
I tried using the latest version of the JDBC Driver (3.28.0) but that does not help.
The only thing I can think to do on the Log4j side is to add a setting to forcibly disable batching even when the driver says it supports it. This would cause the appender to immediately execute SQL INSERT statements instead of batching them.
> "Values not bound to statement" when using JDBC appender
> ---------------------------------------------------------
>
> Key: LOG4J2-2667
> URL: https://issues.apache.org/jira/browse/LOG4J2-2667
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders, Core
> Affects Versions: 2.11.2, 2.12.0
> Environment: Oracle Java 11.0.3, Windows Server 2016, Spring Boot 2.1.6
> Reporter: Edith Chui
> Priority: Major
> Attachments: log4j2.issue.zip
>
>
>
> Since version 2.11.2, the log4j2 library was unable to log message on database via JDBC connection. When using 2.11.1, no such problem was found.
> root cause:
> In org.sqlite.core.CorePreparedStatement, below function was called, but paramValid local variable is not initialized. Value of "paramValid.cardinality()" is always 0 which does not match with the total number of parameter.
>
> {code:java}
> protected void checkParameters() throws SQLException
> {
> if (paramValid.cardinality() != paramCount)
> throw new SQLException("Values not bound to statement");
> }
> {code}
>
> Sample appender in log4j2.xml
> {code:java}
> <JDBC name="jdbcAppender" tableName="LOG_TABLE" bufferSize="0">
> <ConnectionFactory class="MY.SQLiteConnectionFactory" method="getDatabaseConnection" />
> <ColumnMapping name="FIELD1" type="java.lang.Integer" pattern="%X{FIELD1}" />
> <ColumnMapping name="FIELD2" type="java.lang.String" pattern="%X{FIELD2}" />
> <ColumnMapping name="FIELD3" type="java.lang.String" pattern="%X{FIELD3}" />
> <ColumnMapping name="FIELD4" type="java.sql.Types.TIMESTAMP" pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}" />
> </JDBC>{code}
>
> {panel:title=Exception Log}
> 2019-08-02 15:57:45,483 main ERROR An exception occurred processing Appender jdbcAppender org.apache.logging.log4j.core.appender.db.DbAppenderLoggingException: Failed to commit transaction logging event or flushing buffer.
> at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.commitAndClose(JdbcDatabaseManager.java:552)
> at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeThrough(JdbcDatabaseManager.java:867)
> 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.config.LoggerConfig.callAppenders(LoggerConfig.java:464)
> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:448)
> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
> at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
> at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
> at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
> at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2007)
> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1866)
> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179)
> ...
> Caused by: java.sql.SQLException: Values not bound to statement
> at org.sqlite.core.CorePreparedStatement.checkParameters(CorePreparedStatement.java:71)
> at org.sqlite.core.CorePreparedStatement.executeBatch(CorePreparedStatement.java:83)
> at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.commitAndClose(JdbcDatabaseManager.java:545)
> ...
> {panel}
--
This message was sent by Atlassian JIRA
(v7.6.14#76016)