[
https://issues.apache.org/jira/browse/LOG4J2-2496?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Gary Gregory closed LOG4J2-2496.
--------------------------------
Resolution: Fixed
In git {{master}} and {{release-2.x}}.
> 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)
