#46 - Refactor reduce Loggers to single common "io.ebean.datasource"

Author: rbygrave

ebean-datasource-api/src/main/java/io/ebean/datasource/PostgresInitDatabase.java

@@ -12,7 +12,7 @@
  */
 public class PostgresInitDatabase implements InitDatabase {
 
-  private static final Logger log = LoggerFactory.getLogger(PostgresInitDatabase.class);
+  private static final Logger log = LoggerFactory.getLogger("io.ebean.datasource");
 
   @Override
   public void run(Connection connection, DataSourceConfig config) throws SQLException {

ebean-datasource/src/main/java/io/ebean/datasource/pool/BusyConnectionBuffer.java

@@ -1,8 +1,5 @@
 package io.ebean.datasource.pool;
 
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-
 import java.util.Arrays;
 
 /**
@@ -16,8 +13,6 @@
  */
 final class BusyConnectionBuffer {
 
-  private static final Logger logger = LoggerFactory.getLogger(BusyConnectionBuffer.class);
-
   private PooledConnection[] slots;
   private final int growBy;
   private int size;
@@ -78,7 +73,7 @@ boolean remove(PooledConnection pc) {
     int slotId = pc.getSlotId();
     if (slots[slotId] != pc) {
       PooledConnection heldBy = slots[slotId];
-      logger.warn("Failed to remove from slot[{}] PooledConnection[{}] - HeldBy[{}]", pc.getSlotId(), pc, heldBy);
+      Log.log.warn("Failed to remove from slot[{}] PooledConnection[{}] - HeldBy[{}]", pc.getSlotId(), pc, heldBy);
       return false;
     }
     slots[slotId] = null;
@@ -91,7 +86,7 @@ boolean remove(PooledConnection pc) {
    */
   void closeBusyConnections(long leakTimeMinutes) {
     long olderThanTime = System.currentTimeMillis() - (leakTimeMinutes * 60000);
-    logger.debug("Closing busy connections using leakTimeMinutes {}", leakTimeMinutes);
+    Log.log.debug("Closing busy connections using leakTimeMinutes {}", leakTimeMinutes);
     for (int i = 0; i < slots.length; i++) {
       if (slots[i] != null) {
         //tmp.add(slots[i]);
@@ -111,11 +106,11 @@ void closeBusyConnections(long leakTimeMinutes) {
 
   private void closeBusyConnection(PooledConnection pc) {
     try {
-      logger.warn("DataSourcePool closing busy connection? " + pc.getFullDescription());
+      Log.log.warn("DataSourcePool closing busy connection? " + pc.getFullDescription());
       System.out.println("CLOSING busy connection: " + pc.getFullDescription());
       pc.closeConnectionFully(false);
     } catch (Exception ex) {
-      logger.error("Error when closing potentially leaked connection " + pc.getDescription(), ex);
+      Log.log.error("Error when closing potentially leaked connection " + pc.getDescription(), ex);
     }
   }
 
@@ -124,13 +119,13 @@ private void closeBusyConnection(PooledConnection pc) {
    */
   String getBusyConnectionInformation(boolean toLogger) {
     if (toLogger) {
-      logger.info("Dumping [{}] busy connections: (Use datasource.xxx.capturestacktrace=true  ... to get stackTraces)", size());
+      Log.log.info("Dumping [{}] busy connections: (Use datasource.xxx.capturestacktrace=true  ... to get stackTraces)", size());
     }
     StringBuilder sb = new StringBuilder();
     for (PooledConnection pc : slots) {
       if (pc != null) {
         if (toLogger) {
-          logger.info("Busy Connection - {}", pc.getFullDescription());
+          Log.log.info("Busy Connection - {}", pc.getFullDescription());
         } else {
           sb.append(pc.getFullDescription()).append("\r\n");
         }

ebean-datasource/src/main/java/io/ebean/datasource/pool/ConnectionPool.java

@@ -9,7 +9,6 @@
 import io.ebean.datasource.InitDatabase;
 import io.ebean.datasource.PoolStatus;
 import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
 
 import java.io.PrintWriter;
 import java.sql.Connection;
@@ -42,7 +41,7 @@
  */
 public final class ConnectionPool implements DataSourcePool {
 
-  private static final Logger logger = LoggerFactory.getLogger(ConnectionPool.class);
+  private static final Logger log = Log.log;
 
   private final ReentrantLock heartbeatLock = new ReentrantLock(false);
   private final ReentrantLock notifyLock = new ReentrantLock(false);
@@ -200,12 +199,12 @@ private void initialiseConnections() throws SQLException {
         "] min[" + minConnections +
         "] max[" + maxConnections +
         "] in[" + (System.currentTimeMillis() - start) + "ms]";
-      logger.info(msg);
+      log.info(msg);
     } catch (SQLException e) {
       if (failOnStart) {
         throw e;
       }
-      logger.error("Error trying to ensure minimum connections, maybe db server is down - message:" + e.getMessage(), e);
+      log.error("Error trying to ensure minimum connections, maybe db server is down - message:" + e.getMessage(), e);
     }
   }
 
@@ -219,7 +218,7 @@ private void initialiseDatabase() throws SQLException {
       // successfully obtained a connection so skip initDatabase
       connection.clearWarnings();
     } catch (SQLException e) {
-      logger.info("Obtaining connection using ownerUsername:{} to initialise database", config.getOwnerUsername());
+      log.info("Obtaining connection using ownerUsername:{} to initialise database", config.getOwnerUsername());
       // expected when user does not exist, obtain a connection using owner credentials
       try (Connection ownerConnection = createUnpooledConnection(config.getOwnerUsername(), config.getOwnerPassword())) {
         // initialise the DB (typically create the user/role using the owner credentials etc)
@@ -304,7 +303,7 @@ public SQLException getDataSourceDownReason() {
   void notifyWarning(String msg) {
     if (inWarningMode.compareAndSet(false, true)) {
       // send an Error to the event log...
-      logger.warn(msg);
+      log.warn(msg);
       if (notify != null) {
         notify.dataSourceWarning(this, msg);
       }
@@ -325,7 +324,7 @@ private void notifyDown(SQLException reason) {
         // check and set false immediately so that we only alert once
         dataSourceUp.set(false);
         dataSourceDownReason = reason;
-        logger.error("FATAL: DataSourcePool [" + name + "] is down or has network error!!!", reason);
+        log.error("FATAL: DataSourcePool [" + name + "] is down or has network error!!!", reason);
         if (notify != null) {
           notify.dataSourceDown(this, reason);
         }
@@ -350,12 +349,12 @@ private void notifyUp() {
         dataSourceUp.set(true);
         startHeartBeatIfStopped();
         dataSourceDownReason = null;
-        logger.error("RESOLVED FATAL: DataSourcePool [" + name + "] is back up!");
+        log.error("RESOLVED FATAL: DataSourcePool [" + name + "] is back up!");
         if (notify != null) {
           notify.dataSourceUp(this);
         }
       } else {
-        logger.info("DataSourcePool [" + name + "] is back up!");
+        log.info("DataSourcePool [{}] is back up!", name);
       }
     } finally {
       notifyLock.unlock();
@@ -371,7 +370,7 @@ private void trimIdleConnections() {
         queue.trim(maxInactiveMillis, maxAgeMillis);
         lastTrimTime = System.currentTimeMillis();
       } catch (Exception e) {
-        logger.error("Error trying to trim idle connections - message:" + e.getMessage(), e);
+        log.error("Error trying to trim idle connections - message:" + e.getMessage(), e);
       }
     }
   }
@@ -401,7 +400,7 @@ private void checkDataSource() {
           conn.close();
         }
       } catch (SQLException ex) {
-        logger.warn("Can't close connection in checkDataSource!");
+        log.warn("Can't close connection in checkDataSource!");
       }
     }
   }
@@ -556,14 +555,14 @@ private boolean testConnection(Connection conn) throws SQLException {
           rset.close();
         }
       } catch (SQLException e) {
-        logger.error("Error closing resultSet", e);
+        log.error("Error closing resultSet", e);
       }
       try {
         if (stmt != null) {
           stmt.close();
         }
       } catch (SQLException e) {
-        logger.error("Error closing statement", e);
+        log.error("Error closing statement", e);
       }
     }
   }
@@ -575,7 +574,7 @@ boolean validateConnection(PooledConnection conn) {
     try {
       return testConnection(conn);
     } catch (Exception e) {
-      logger.warn("heartbeatsql test failed on connection:" + conn.getName() + " message:" + e.getMessage());
+      log.warn("Heartbeat test failed on connection:" + conn.getName() + " message:" + e.getMessage());
       return false;
     }
   }
@@ -617,7 +616,7 @@ private void returnTheConnection(PooledConnection pooledConnection, boolean forc
 
   void returnConnectionReset(PooledConnection pooledConnection) {
     queue.returnPooledConnection(pooledConnection, true);
-    logger.warn("Resetting DataSourcePool on read-only failure [{}]", name);
+    log.warn("Resetting DataSourcePool on read-only failure [{}]", name);
     reset();
   }
 
@@ -739,7 +738,7 @@ public void offline() {
   private void shutdownPool(boolean closeBusyConnections) {
     stopHeartBeatIfRunning();
     PoolStatus status = queue.shutdown(closeBusyConnections);
-    logger.info("DataSourcePool [{}] shutdown {}  psc[hit:{} miss:{} put:{} rem:{}]", name, status, pscHit, pscMiss, pscPut, pscRem);
+    log.info("DataSourcePool [{}] shutdown {}  psc[hit:{} miss:{} put:{} rem:{}]", name, status, pscHit, pscMiss, pscPut, pscRem);
     dataSourceUp.set(false);
   }
 

ebean-datasource/src/main/java/io/ebean/datasource/pool/FreeConnectionBuffer.java

@@ -1,8 +1,5 @@
 package io.ebean.datasource.pool;
 
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-
 import java.util.ArrayList;
 import java.util.Iterator;
 import java.util.LinkedList;
@@ -16,8 +13,6 @@
  */
 final class FreeConnectionBuffer {
 
-  private static final Logger logger = LoggerFactory.getLogger(FreeConnectionBuffer.class);
-
   /**
    * Buffer oriented for add and remove.
    */
@@ -60,7 +55,7 @@ PooledConnection remove() {
   void closeAll(boolean logErrors) {
     List<PooledConnection> tempList = new ArrayList<>(freeBuffer);
     freeBuffer.clear();
-    logger.debug("... closing all {} connections from the free list with logErrors: {}", tempList.size(), logErrors);
+    Log.log.trace("... closing all {} connections from the free list with logErrors: {}", tempList.size(), logErrors);
     for (PooledConnection connection : tempList) {
       connection.closeConnectionFully(logErrors);
     }

ebean-datasource/src/main/java/io/ebean/datasource/pool/Log.java

@@ -0,0 +1,13 @@
+package io.ebean.datasource.pool;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * Common Logger instance for datasource implementation.
+ */
+final class Log {
+
+  static final Logger log = LoggerFactory.getLogger("io.ebean.datasource");
+
+}

ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnection.java

@@ -30,7 +30,7 @@
  */
 final class PooledConnection extends ConnectionDelegator {
 
-  private static final Logger logger = LoggerFactory.getLogger(PooledConnection.class);
+  private static final Logger log = Log.log;
 
   private static final String IDLE_CONNECTION_ACCESSED_ERROR = "Pooled Connection has been accessed whilst idle in the pool, via method: ";
 
@@ -211,22 +211,22 @@ public void setLongRunning(boolean longRunning) {
    * @param logErrors if false then don't log errors when closing
    */
   void closeConnectionFully(boolean logErrors) {
-    if (logger.isDebugEnabled()) {
-      logger.debug("Closing Connection[{}] slot[{}] reason[{}], pstmtStats: {} ", name, slotId, closeReason, pstmtCache.description());
+    if (log.isTraceEnabled()) {
+      log.trace("Closing Connection[{}] slot[{}] reason[{}], pstmtStats: {} ", name, slotId, closeReason, pstmtCache.description());
     }
     if (pool != null) {
       pool.pstmtCacheMetrics(pstmtCache);
     }
     try {
       if (connection.isClosed()) {
-        // Typically the JDBC Driver has its own JVM shutdown hook and already
+        // Typically, the JDBC Driver has its own JVM shutdown hook and already
         // closed the connections in our DataSource pool so making this DEBUG level
-        logger.debug("Closing Connection[{}] that is already closed?", name);
+        log.trace("Closing Connection[{}] that is already closed?", name);
         return;
       }
     } catch (SQLException ex) {
       if (logErrors) {
-        logger.error("Error checking if connection [" + name + "] is closed", ex);
+        log.error("Error checking if connection [" + name + "] is closed", ex);
       }
     }
     try {
@@ -235,15 +235,15 @@ void closeConnectionFully(boolean logErrors) {
       }
     } catch (SQLException ex) {
       if (logErrors) {
-        logger.warn("Error when closing connection Statements", ex);
+        log.warn("Error when closing connection Statements", ex);
       }
     }
     try {
       connection.close();
       pool.dec();
     } catch (SQLException ex) {
-      if (logErrors || logger.isDebugEnabled()) {
-        logger.error("Error when fully closing connection [" + getFullDescription() + "]", ex);
+      if (logErrors || log.isDebugEnabled()) {
+        log.error("Error when fully closing connection [" + getFullDescription() + "]", ex);
       }
     }
   }
@@ -290,7 +290,7 @@ void returnPreparedStatement(ExtendedPreparedStatement pstmt) {
           // Already an entry in the cache with the exact same SQL...
           pstmt.closeDestroy();
         } catch (SQLException e) {
-          logger.error("Error closing Pstmt", e);
+          log.error("Error closing PreparedStatement", e);
         }
       }
     } finally {
@@ -447,7 +447,7 @@ public void close() throws SQLException {
 
     } catch (Exception ex) {
       // the connection is BAD, remove it, close it and test the pool
-      logger.warn("Error when trying to return connection to pool, closing fully.", ex);
+      log.warn("Error when trying to return connection to pool, closing fully.", ex);
       pool.returnConnectionForceClose(this);
     }
   }
@@ -467,11 +467,11 @@ protected void finalize() throws Throwable {
     try {
       if (connection != null && !connection.isClosed()) {
         // connect leak?
-        logger.warn("Closing Connection on finalize() - {}", getFullDescription());
+        log.warn("Closing Connection on finalize() - {}", getFullDescription());
         closeConnectionFully(false);
       }
     } catch (Exception e) {
-      logger.error("Error when finalize is closing a connection? (unexpected)", e);
+      log.error("Error when finalize is closing a connection? (unexpected)", e);
     }
     super.finalize();
   }