Log4j 2
  1. Log4j 2
  2. LOG4J2-407

JDBCAppender cannot recover from loss of database connectivity

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta9
    • Fix Version/s: 2.0-rc1
    • Component/s: Appenders
    • Labels:
      None

      Description

      The JDBCAppender holds a single database connection for all its logging. If that database connection is closed, it does not attempt to make a new connection.

      Many connection pools automatically close connections after a certain amount of inactivity. (This can be worked around by properly configuring a pool).

      Database connectivity issues are also common enough that a long running application may experience temporary network issues. When the network comes back online, the logging will not resume.

      I've been meaning to submit a patch for this, but I haven't gotten to it. Since I saw that you are looking to come out of beta soon, I thought I would log this issue in case someone else has time to write the patch before I get to it.

        Issue Links

          Activity

          Hide
          Michael Kloster added a comment -

          Great news! I am on vacation but will be able to validate this fix on my
          end mid next week if someone else has not validated sooner.

          Michael

          Show
          Michael Kloster added a comment - Great news! I am on vacation but will be able to validate this fix on my end mid next week if someone else has not validated sooner. Michael
          Hide
          Nick Williams added a comment -

          Fixed with r1565858 and r1565878. The database appenders now connect to the database (i.e., borrow from the connection pool) and begin a transaction on every flush or every non-buffered writeInternal, then commit and disconnect (i.e., return to pool) at the end of the flush or non-buffered writeInternal.

          Note also that the <DriverManager...> connection source plugin is no longer available. It was removed because it was unsafe and didn't support connection pooling. Please use the <DataSource...> or <ConnectionFactory...> connection source plugins, instead.

          Show
          Nick Williams added a comment - Fixed with r1565858 and r1565878. The database appenders now connect to the database (i.e., borrow from the connection pool) and begin a transaction on every flush or every non-buffered writeInternal , then commit and disconnect (i.e., return to pool) at the end of the flush or non-buffered writeInternal . Note also that the <DriverManager...> connection source plugin is no longer available. It was removed because it was unsafe and didn't support connection pooling. Please use the <DataSource...> or <ConnectionFactory...> connection source plugins, instead.
          Hide
          Matt Sicker added a comment -

          One possibility would be to use Commons Pool for pooling Connection objects. It's no good to keep closing connection objects from what I recall.

          Show
          Matt Sicker added a comment - One possibility would be to use Commons Pool for pooling Connection objects. It's no good to keep closing connection objects from what I recall.
          Hide
          Matt Sicker added a comment -

          The problem with that is there's a contract on the AbstractDatabaseAppender that writeInternal() won't call connect() more than once. Then again, this isn't using the super.connect() method, so that might be a better idea.

          Show
          Matt Sicker added a comment - The problem with that is there's a contract on the AbstractDatabaseAppender that writeInternal() won't call connect() more than once. Then again, this isn't using the super.connect() method, so that might be a better idea.
          Hide
          Dimitry Declercq added a comment -

          Would you retrieve a connection from the ConnectionSource on each writeInternal then? Something as such:

              @Override
              protected void writeInternal(final LogEvent event) {
                  Connection connection = this.connectionSource.getConnection();
                  PreparedStatement statement = connection.prepareStatement(this.sqlStatement);
                  ...
                  Closer.closeSilent(connection);
          

          Should work, I don't know the overhead of preparing the statement each time vs one-time prepare...

          Show
          Dimitry Declercq added a comment - Would you retrieve a connection from the ConnectionSource on each writeInternal then? Something as such: @Override protected void writeInternal( final LogEvent event) { Connection connection = this .connectionSource.getConnection(); PreparedStatement statement = connection.prepareStatement( this .sqlStatement); ... Closer.closeSilent(connection); Should work, I don't know the overhead of preparing the statement each time vs one-time prepare...
          Hide
          Matt Sicker added a comment -

          The DataSourceConnectionSource is already a sort of connection pool considering how it's normally implemented. An actual connection pool would be necessary for the DriverManagerConnectionSource so that connections can be opened and closed for each log event or batch update.

          Show
          Matt Sicker added a comment - The DataSourceConnectionSource is already a sort of connection pool considering how it's normally implemented. An actual connection pool would be necessary for the DriverManagerConnectionSource so that connections can be opened and closed for each log event or batch update.
          Hide
          Thomas Neidhart added a comment -

          Yes, a connection pool would be the best solution imho, but make it flexible by providing a data source to the JDBCAppender.

          Show
          Thomas Neidhart added a comment - Yes, a connection pool would be the best solution imho, but make it flexible by providing a data source to the JDBCAppender.
          Hide
          Dimitry Declercq added a comment -

          Michael, I like your idea very much. How we use the Log4J here, is through a fully configured BoneCP connection pool which indeed already does checking. As you stated, the problem is that the current implementation just uses a single connection.

          I think that in terms of performance it might actually be faster if you implement it so as it can request multiple connections from a pool for parallel processing. If this isn't possible you could mitigate performance drawbacks (if any) by using the buffer attribute and only requesting a new connection from the pool on each buffer iteration.

          I'm not sure if a "isPooled" flag would be needed, just close and open a connection by default and document this behaviour with a addition that a ConnectionPool is strongly required for intensive logging. I suspect that most enterprise applications or applications generating lots of data would already use a pool.

          I think there are now 2 approaches in this Issue that are under discussion:

          • Reconnect on exception/disconnect (as explained by Thomas Neidhart)
          • Redo the connection management and open/close on each (batch of) logging event, especially in the case when a connection pool is used (as explained by Michael Kloster)

          I'm more in favor of the second for a long term solution, but as a quickfix I wrote some code doing the first. I was unable to test my code today, I hope to be able to provide quickfix by friday (my application needs it bad),

          Show
          Dimitry Declercq added a comment - Michael, I like your idea very much. How we use the Log4J here, is through a fully configured BoneCP connection pool which indeed already does checking. As you stated, the problem is that the current implementation just uses a single connection. I think that in terms of performance it might actually be faster if you implement it so as it can request multiple connections from a pool for parallel processing. If this isn't possible you could mitigate performance drawbacks (if any) by using the buffer attribute and only requesting a new connection from the pool on each buffer iteration. I'm not sure if a "isPooled" flag would be needed, just close and open a connection by default and document this behaviour with a addition that a ConnectionPool is strongly required for intensive logging. I suspect that most enterprise applications or applications generating lots of data would already use a pool. I think there are now 2 approaches in this Issue that are under discussion: Reconnect on exception/disconnect (as explained by Thomas Neidhart) Redo the connection management and open/close on each (batch of) logging event, especially in the case when a connection pool is used (as explained by Michael Kloster) I'm more in favor of the second for a long term solution, but as a quickfix I wrote some code doing the first. I was unable to test my code today, I hope to be able to provide quickfix by friday (my application needs it bad),
          Hide
          Michael Kloster added a comment -

          Another approach to this problem would be to take advantage of the connection pool. At this point, you can set up a connection pool (via the JDBC Datasource) for the logger, but it is just used once to get a single connection that is held by the logger and never returned to the pool.

          If the logger requested a connection from the pool and returned it after each use, the connection pool can be configured to check connection validity (or not) depending on the application need for performance. If the pool can't give the logger a valid connection, then you can throw an exception without further logic.

          I have never benchmarked the processes of taking/returning a connection from a pool but I've always imagined it to be about as fast as taking an object from a dictionary. Is that not the case?

          One issue I see with this suggestion is it makes an assumption that a pool is configured. Maybe this could be overcome with a "isPooled" flag. Then the appender could supply its own 'poor man's' version of a pool like it does now if the connection is not marked as pooled.

          Show
          Michael Kloster added a comment - Another approach to this problem would be to take advantage of the connection pool. At this point, you can set up a connection pool (via the JDBC Datasource) for the logger, but it is just used once to get a single connection that is held by the logger and never returned to the pool. If the logger requested a connection from the pool and returned it after each use, the connection pool can be configured to check connection validity (or not) depending on the application need for performance. If the pool can't give the logger a valid connection, then you can throw an exception without further logic. I have never benchmarked the processes of taking/returning a connection from a pool but I've always imagined it to be about as fast as taking an object from a dictionary. Is that not the case? One issue I see with this suggestion is it makes an assumption that a pool is configured. Maybe this could be overcome with a "isPooled" flag. Then the appender could supply its own 'poor man's' version of a pool like it does now if the connection is not marked as pooled.
          Hide
          Dimitry Declercq added a comment -

          Now the first check will fail because 'this.connection.isClosed()' returns true, so it throws the AppenderLoggingException. I might be missing it, but placing code after that throw would result in the reconnect not being executed, so I placed it before the throw (but I might be overlooking something).

          For your complete fix, special attention should be given to cases in which the database or network is down, as to not end-up in a endless loop of reconnects and retries. This can offcourse be resolved as simple as by adding a counter that only tries x times.
          Also, the SQLException is never thrown at this moment, the check on the connection returns with a AppenderLoggingException.
          Offcourse, these are all small things that when programming a complete fix would probably be dealt with anyway

          PS: I wouldn't want to do a ping every time a logevent occurs, so always executing a this.connection.isValid(t) seems a bit overkill. I think (although not tested) that this would decimate performance for both the application and the DB server.

          Show
          Dimitry Declercq added a comment - Now the first check will fail because 'this.connection.isClosed()' returns true, so it throws the AppenderLoggingException. I might be missing it, but placing code after that throw would result in the reconnect not being executed, so I placed it before the throw (but I might be overlooking something). For your complete fix, special attention should be given to cases in which the database or network is down, as to not end-up in a endless loop of reconnects and retries. This can offcourse be resolved as simple as by adding a counter that only tries x times. Also, the SQLException is never thrown at this moment, the check on the connection returns with a AppenderLoggingException. Offcourse, these are all small things that when programming a complete fix would probably be dealt with anyway PS: I wouldn't want to do a ping every time a logevent occurs, so always executing a this.connection.isValid(t) seems a bit overkill. I think (although not tested) that this would decimate performance for both the application and the DB server.
          Hide
          Thomas Neidhart added a comment -

          No, if you place it there, it will not work.

          It was intentionally placed after the first check.
          A complete fix would do it differently though:

          • if an SQLException is caught -> check if the connection is still valid
          • re-connect
          • if re-connect was successful -> re-try writing the log entry
          Show
          Thomas Neidhart added a comment - No, if you place it there, it will not work. It was intentionally placed after the first check. A complete fix would do it differently though: if an SQLException is caught -> check if the connection is still valid re-connect if re-connect was successful -> re-try writing the log entry
          Hide
          Dimitry Declercq added a comment -

          I'm guessing you would want to do that before the check that throws the AppenderLoggingExcpetion.
          I created a similar solution yesterday with the intention to test this today or tomorrow. This is probably not the best nor the cleanest solution, but rather a quickfix that shouldn't impact performance too much.

              @Override
              protected void writeInternal(final LogEvent event) {
                  StringReader reader = null;
                  try {
                      if ( !this.isConnected() || this.connection == null || this.connection.isClosed() ) {
                          // Check if the connection has been closed
                          // You don't want to execute isValid always, since this launches a query/ping to the server
                          if ( this.connection != null && !this.connection.isValid(3) ) {
                              // Try to re-establish connection with database
                              disconnectInternal();
                              connectInternal();
                          }
          
                          // Check if we were able to recover the connection
                          if ( this.connection == null || this.connection.isClosed() ) {
                              // Nope, connection is dead...
                              throw new AppenderLoggingException("Cannot write logging event; JDBC manager not connected to the database.");
                          }
                      }
          
          Show
          Dimitry Declercq added a comment - I'm guessing you would want to do that before the check that throws the AppenderLoggingExcpetion. I created a similar solution yesterday with the intention to test this today or tomorrow. This is probably not the best nor the cleanest solution, but rather a quickfix that shouldn't impact performance too much. @Override protected void writeInternal( final LogEvent event) { StringReader reader = null ; try { if ( ! this .isConnected() || this .connection == null || this .connection.isClosed() ) { // Check if the connection has been closed // You don't want to execute isValid always, since this launches a query/ping to the server if ( this .connection != null && ! this .connection.isValid(3) ) { // Try to re-establish connection with database disconnectInternal(); connectInternal(); } // Check if we were able to recover the connection if ( this .connection == null || this .connection.isClosed() ) { // Nope, connection is dead... throw new AppenderLoggingException( "Cannot write logging event; JDBC manager not connected to the database." ); } }
          Hide
          Thomas Neidhart added a comment -

          A solution could be to use the new method Connection.isValid() which seems to query the database. Using the isClosed() can not be used for this purpose.
          See the code snippet below, added to the JDBCDatabaseManager. The idea is that if we detect that the connection has been closed due to a timeout, we try to re-establish it.
          I used a timeout of 1s, but this should maybe better made configurable.

              @Override
              protected void writeInternal(final LogEvent event) {
                  StringReader reader = null;
                  try {
                      if (!this.isConnected() || this.connection == null || this.connection.isClosed()) {
                          throw new AppenderLoggingException(
                                  "Cannot write logging event; JDBC manager not connected to the database.");
                      }
          
                      // the connection was opened before but may have been closed automatically due to a timeout
                      // try to re-establish connection to the database
                      if ( !this.connection.isValid( 1 )) {
                          disconnectInternal();
                          connectInternal();
                      }
          
          
          Show
          Thomas Neidhart added a comment - A solution could be to use the new method Connection.isValid() which seems to query the database. Using the isClosed() can not be used for this purpose. See the code snippet below, added to the JDBCDatabaseManager. The idea is that if we detect that the connection has been closed due to a timeout, we try to re-establish it. I used a timeout of 1s, but this should maybe better made configurable. @Override protected void writeInternal(final LogEvent event) { StringReader reader = null; try { if (!this.isConnected() || this.connection == null || this.connection.isClosed()) { throw new AppenderLoggingException( "Cannot write logging event; JDBC manager not connected to the database."); } // the connection was opened before but may have been closed automatically due to a timeout // try to re-establish connection to the database if ( !this.connection.isValid( 1 )) { disconnectInternal(); connectInternal(); }
          Hide
          Dimitry Declercq added a comment -

          Any progress on this? I logged an issue yesterday concerning this (before I found this one) LOG4J2-449
          I'm available to test any solution you have for this. We are also conducting some MySQL database tests next week (failover, network failures, ...), if you can provide me with a patched version we can check the behaviour of Log4J in these scenario's as well.

          Show
          Dimitry Declercq added a comment - Any progress on this? I logged an issue yesterday concerning this (before I found this one) LOG4J2-449 I'm available to test any solution you have for this. We are also conducting some MySQL database tests next week (failover, network failures, ...), if you can provide me with a patched version we can check the behaviour of Log4J in these scenario's as well.
          Hide
          Nick Williams added a comment -

          I've been mulling over the best way to approach this for several weeks now. Want it to be elegant and simple but still robust like you say. I have a few ideas that I'm playing with. I intend to make this happen before GA.

          Show
          Nick Williams added a comment - I've been mulling over the best way to approach this for several weeks now. Want it to be elegant and simple but still robust like you say. I have a few ideas that I'm playing with. I intend to make this happen before GA.

            People

            • Assignee:
              Nick Williams
              Reporter:
              Michael Kloster
            • Votes:
              3 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development