[
https://issues.apache.org/jira/browse/LOG4J2-2496?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Gary Gregory updated LOG4J2-2496:
---------------------------------
Description:
The JDBC Appender should reconnect to the database when a database connection
goes stale.
Use case:
* Start Log4j configured with a JDBC Appender to MySQL
* Log an event, all is well, it ends up in the database
* Restart the MySQL Service (MySQL80) directly from the Windows Services app
* Log an event, Log4j does not log the event to the database because the MySQL
JDBC Driver no longer is connected to the database.
For example:
{noformat}
2018-11-01 06:28:14,408 WARN
[server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.dbsapi.acnms.com][EH]
[client <- proxy] 00000018 channel
org.apache.hc.core5.http.impl.nio.ServerHttp1StreamHandler$2@6ab4c7b8
[requestState=COMPLETE, responseState=IDLE,
outputChannel=Http1StreamChannel[80.82.77.33:37422->131.103.20.68:443]]
org.apache.logging.log4j.core.appender.AppenderLoggingException: Cannot write
logging event or flush buffer; JDBC manager cannot connect to the database.
org.apache.logging.log4j.core.appender.AppenderLoggingException: Cannot write
logging event or flush buffer; JDBC manager cannot connect to the database.
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:111)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:208)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:125)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:464)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:448)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1827)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1281)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at ...<my app>
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last
packet successfully received from the server was 31,601,297 milliseconds ago.
The last packet sent successfully to the server was 31,601,297 milliseconds
ago. is longer than the server configured value of 'wait_timeout'. You should
consider either expiring and/or testing connection validity before use in your
application, increasing the server configured values for client timeouts, or
using the Connector/J connection property 'autoReconnect=true' to avoid this
problem.
at
com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2067)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
... 35 more
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: The last packet
successfully received from the server was 31,601,297 milliseconds ago. The
last packet sent successfully to the server was 31,601,297 milliseconds ago. is
longer than the server configured value of 'wait_timeout'. You should consider
either expiring and/or testing connection validity before use in your
application, increasing the server configured values for client timeouts, or
using the Connector/J connection property 'autoReconnect=true' to avoid this
problem.
at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
~[?:1.8.0_181]
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
~[?:1.8.0_181]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
~[?:1.8.0_181]
at java.lang.reflect.Constructor.newInstance(Unknown Source)
~[?:1.8.0_181]
at
com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:587)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:648)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:980)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:915)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1182)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2057)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
... 35 more
Caused by: java.net.SocketException: Connection reset by peer: socket write
error
at java.net.SocketOutputStream.socketWrite0(Native Method)
~[?:1.8.0_181]
at java.net.SocketOutputStream.socketWrite(Unknown Source)
~[?:1.8.0_181]
at java.net.SocketOutputStream.write(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.OutputRecord.writeBuffer(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.OutputRecord.write(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.SSLSocketImpl.writeRecordInternal(Unknown
Source) ~[?:1.8.0_181]
at sun.security.ssl.SSLSocketImpl.writeRecord(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.AppOutputStream.write(Unknown Source)
~[?:1.8.0_181]
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
~[?:1.8.0_181]
at java.io.BufferedOutputStream.flush(Unknown Source)
~[?:1.8.0_181]
at
com.mysql.cj.protocol.a.SimplePacketSender.send(SimplePacketSender.java:55)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.TimeTrackingPacketSender.send(TimeTrackingPacketSender.java:50)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:578)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:648)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:980)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:915)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1182)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2057)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
... 35 more
{noformat}
The JMS Appender already provides an implementation pattern on how to do this.
This improvement adds the JDBC Appender attribute {{reconnectIntervalMillis}}
with a default of 5000.
was:
The JDBC Appender should reconnect to the database when a database connection
goes stale.
Use case:
* Start Log4j configured with a JDBC Appender to MySQL
* Log an event, all is well, it ends up in the database
* Restart the MySQL Service (MySQL80) directly from the Windows Services app
* Log an event, Log4j does not log the event to the database because the MySQL
JDBC Driver no longer is connected to the database.
For example:
{noformat}
2018-11-01 06:28:14,408 WARN
[server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.dbsapi.acnms.com][EH]
[client <- proxy] 00000018 channel
org.apache.hc.core5.http.impl.nio.ServerHttp1StreamHandler$2@6ab4c7b8
[requestState=COMPLETE, responseState=IDLE,
outputChannel=Http1StreamChannel[80.82.77.33:37422->131.103.20.68:443]]
org.apache.logging.log4j.core.appender.AppenderLoggingException: Cannot write
logging event or flush buffer; JDBC manager cannot connect to the database.
org.apache.logging.log4j.core.appender.AppenderLoggingException: Cannot write
logging event or flush buffer; JDBC manager cannot connect to the database.
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:111)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:208)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:125)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:464)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:448)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1827)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at
org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1281)
~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
at ...<my app>
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last
packet successfully received from the server was 31,601,297 milliseconds ago.
The last packet sent successfully to the server was 31,601,297 milliseconds
ago. is longer than the server configured value of 'wait_timeout'. You should
consider either expiring and/or testing connection validity before use in your
application, increasing the server configured values for client timeouts, or
using the Connector/J connection property 'autoReconnect=true' to avoid this
problem.
at
com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2067)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
... 35 more
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: The last packet
successfully received from the server was 31,601,297 milliseconds ago. The
last packet sent successfully to the server was 31,601,297 milliseconds ago. is
longer than the server configured value of 'wait_timeout'. You should consider
either expiring and/or testing connection validity before use in your
application, increasing the server configured values for client timeouts, or
using the Connector/J connection property 'autoReconnect=true' to avoid this
problem.
at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
~[?:1.8.0_181]
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
~[?:1.8.0_181]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
~[?:1.8.0_181]
at java.lang.reflect.Constructor.newInstance(Unknown Source)
~[?:1.8.0_181]
at
com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:587)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:648)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:980)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:915)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1182)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2057)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
... 35 more
Caused by: java.net.SocketException: Connection reset by peer: socket write
error
at java.net.SocketOutputStream.socketWrite0(Native Method)
~[?:1.8.0_181]
at java.net.SocketOutputStream.socketWrite(Unknown Source)
~[?:1.8.0_181]
at java.net.SocketOutputStream.write(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.OutputRecord.writeBuffer(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.OutputRecord.write(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.SSLSocketImpl.writeRecordInternal(Unknown
Source) ~[?:1.8.0_181]
at sun.security.ssl.SSLSocketImpl.writeRecord(Unknown Source)
~[?:1.8.0_181]
at sun.security.ssl.AppOutputStream.write(Unknown Source)
~[?:1.8.0_181]
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
~[?:1.8.0_181]
at java.io.BufferedOutputStream.flush(Unknown Source)
~[?:1.8.0_181]
at
com.mysql.cj.protocol.a.SimplePacketSender.send(SimplePacketSender.java:55)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.TimeTrackingPacketSender.send(TimeTrackingPacketSender.java:50)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:578)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:648)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:980)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:915)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1182)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2057)
~[mysql-connector-java-8.0.12.jar:8.0.12]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
~[commons-dbcp2-2.2.0.jar:2.2.0]
at
org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
... 35 more
{noformat}
The JMS Appender already provides an implementation pattern on how to do this.
> JDBC Appender should reconnect to the database when a connection goes stale
> ---------------------------------------------------------------------------
>
> Key: LOG4J2-2496
> URL: https://issues.apache.org/jira/browse/LOG4J2-2496
> Project: Log4j 2
> Issue Type: Improvement
> Components: Appenders
> Reporter: Gary Gregory
> Assignee: Gary Gregory
> Priority: Major
> Fix For: 3.0.0, 2.11.2
>
>
> The JDBC Appender should reconnect to the database when a database connection
> goes stale.
> Use case:
> * Start Log4j configured with a JDBC Appender to MySQL
> * Log an event, all is well, it ends up in the database
> * Restart the MySQL Service (MySQL80) directly from the Windows Services app
> * Log an event, Log4j does not log the event to the database because the
> MySQL JDBC Driver no longer is connected to the database.
> For example:
> {noformat}
> 2018-11-01 06:28:14,408 WARN
> [server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.dbsapi.acnms.com][EH]
> [client <- proxy] 00000018 channel
> org.apache.hc.core5.http.impl.nio.ServerHttp1StreamHandler$2@6ab4c7b8
> [requestState=COMPLETE, responseState=IDLE,
> outputChannel=Http1StreamChannel[80.82.77.33:37422->131.103.20.68:443]]
> org.apache.logging.log4j.core.appender.AppenderLoggingException: Cannot write
> logging event or flush buffer; JDBC manager cannot connect to the database.
> org.apache.logging.log4j.core.appender.AppenderLoggingException: Cannot write
> logging event or flush buffer; JDBC manager cannot connect to the database.
> at
> org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:111)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:208)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:125)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:464)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:448)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
> ~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
> ~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
> ~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1827)
> ~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at
> org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1281)
> ~[log4j-api-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> at ...<my app>
> Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last
> packet successfully received from the server was 31,601,297 milliseconds ago.
> The last packet sent successfully to the server was 31,601,297 milliseconds
> ago. is longer than the server configured value of 'wait_timeout'. You should
> consider either expiring and/or testing connection validity before use in
> your application, increasing the server configured values for client
> timeouts, or using the Connector/J connection property 'autoReconnect=true'
> to avoid this problem.
> at
> com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2067)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
> ~[commons-dbcp2-2.2.0.jar:2.2.0]
> at
> org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
> ~[commons-dbcp2-2.2.0.jar:2.2.0]
> at
> org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> ... 35 more
> Caused by: com.mysql.cj.exceptions.CJCommunicationsException: The last packet
> successfully received from the server was 31,601,297 milliseconds ago. The
> last packet sent successfully to the server was 31,601,297 milliseconds ago.
> is longer than the server configured value of 'wait_timeout'. You should
> consider either expiring and/or testing connection validity before use in
> your application, increasing the server configured values for client
> timeouts, or using the Connector/J connection property 'autoReconnect=true'
> to avoid this problem.
> at
> sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> ~[?:1.8.0_181]
> at
> sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
> ~[?:1.8.0_181]
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
> ~[?:1.8.0_181]
> at java.lang.reflect.Constructor.newInstance(Unknown Source)
> ~[?:1.8.0_181]
> at
> com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:587)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:648)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:980)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:915)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.NativeSession.execSQL(NativeSession.java:1182)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2057)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
> ~[commons-dbcp2-2.2.0.jar:2.2.0]
> at
> org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
> ~[commons-dbcp2-2.2.0.jar:2.2.0]
> at
> org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> ... 35 more
> Caused by: java.net.SocketException: Connection reset by peer: socket write
> error
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> ~[?:1.8.0_181]
> at java.net.SocketOutputStream.socketWrite(Unknown Source)
> ~[?:1.8.0_181]
> at java.net.SocketOutputStream.write(Unknown Source)
> ~[?:1.8.0_181]
> at sun.security.ssl.OutputRecord.writeBuffer(Unknown Source)
> ~[?:1.8.0_181]
> at sun.security.ssl.OutputRecord.write(Unknown Source)
> ~[?:1.8.0_181]
> at sun.security.ssl.SSLSocketImpl.writeRecordInternal(Unknown
> Source) ~[?:1.8.0_181]
> at sun.security.ssl.SSLSocketImpl.writeRecord(Unknown Source)
> ~[?:1.8.0_181]
> at sun.security.ssl.AppOutputStream.write(Unknown Source)
> ~[?:1.8.0_181]
> at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
> ~[?:1.8.0_181]
> at java.io.BufferedOutputStream.flush(Unknown Source)
> ~[?:1.8.0_181]
> at
> com.mysql.cj.protocol.a.SimplePacketSender.send(SimplePacketSender.java:55)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.TimeTrackingPacketSender.send(TimeTrackingPacketSender.java:50)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:578)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:648)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:980)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:915)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.NativeSession.execSQL(NativeSession.java:1182)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2057)
> ~[mysql-connector-java-8.0.12.jar:8.0.12]
> at
> org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
> ~[commons-dbcp2-2.2.0.jar:2.2.0]
> at
> org.apache.commons.dbcp2.DelegatingConnection.setAutoCommit(DelegatingConnection.java:543)
> ~[commons-dbcp2-2.2.0.jar:2.2.0]
> at
> org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndStart(JdbcDatabaseManager.java:107)
> ~[log4j-core-2.11.2-SNAPSHOT.jar:2.11.2-SNAPSHOT]
> ... 35 more
> {noformat}
> The JMS Appender already provides an implementation pattern on how to do this.
> This improvement adds the JDBC Appender attribute {{reconnectIntervalMillis}}
> with a default of 5000.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
