#1402 - Refactor SQL Logging internals (io.ebean.SQL) such that it is easier to capture for testing/asserts

src/main/java/io/ebeaninternal/api/SpiEbeanServer.java

@@ -31,6 +31,11 @@ import java.util.function.Predicate;
  */
 public interface SpiEbeanServer extends EbeanServer, BeanLoader, BeanCollectionLoader {
 
+  /**
+   * Return the log manager.
+   */
+  SpiLogManager log();
+
   /**
    * Return the server extended Json context.
    */

src/main/java/io/ebeaninternal/api/SpiLogManager.java

@@ -0,0 +1,27 @@
+package io.ebeaninternal.api;
+
+/**
+ * Log manager for SQL, TXN and Summary logging.
+ * <p>
+ * In general at runtime this uses SLF4J Logger but this abstraction allows us to capture
+ * the logged SQL during testing such that we can assert against the executed sql if desired.
+ * </p>
+ */
+public interface SpiLogManager {
+
+  /**
+   * Return the SQL logger.
+   */
+  SpiLogger sql();
+
+  /**
+   * Return the TXN logger.
+   */
+  SpiLogger txn();
+
+  /**
+   * Return the Summary logger.
+   */
+  SpiLogger sum();
+
+}

src/main/java/io/ebeaninternal/api/SpiLogger.java

@@ -0,0 +1,31 @@
+package io.ebeaninternal.api;
+
+/**
+ * Logger for SQL, TXN and Summary logging.
+ * <p>
+ * In general at runtime this uses SLF4J Logger but this abstraction allows us to capture
+ * the logged SQL during testing such that we can assert against the executed sql if desired.
+ * </p>
+ */
+public interface SpiLogger {
+
+  /**
+   * Is debug logging enabled.
+   */
+  boolean isDebug();
+
+  /**
+   * Is trace logging enabled.
+   */
+  boolean isTrace();
+
+  /**
+   * Log a debug level message.
+   */
+  void debug(String msg);
+
+  /**
+   * Log a trace level message.
+   */
+  void trace(String msg);
+}

src/main/java/io/ebeaninternal/server/core/AbstractSqlQueryRequest.java

@@ -170,11 +170,7 @@ public abstract class AbstractSqlQueryRequest {
     }
 
     if (isLogSql()) {
-      String logSql = TrimLogSql.trim(sql);
-      if (TransactionManager.SQL_LOGGER.isTraceEnabled()) {
-        logSql = Str.add(logSql, "; --bind(", bindLog, ")");
-      }
-      trans.logSql(logSql);
+      trans.logSql(Str.add(TrimLogSql.trim(sql), "; --bind(", bindLog, ")"));
     }
 
     setResultSet(pstmt.executeQuery(), null);

src/main/java/io/ebeaninternal/server/core/DefaultServer.java

@@ -64,6 +64,7 @@ import io.ebeaninternal.api.SpiBackgroundExecutor;
 import io.ebeaninternal.api.SpiDtoQuery;
 import io.ebeaninternal.api.SpiEbeanServer;
 import io.ebeaninternal.api.SpiJsonContext;
+import io.ebeaninternal.api.SpiLogManager;
 import io.ebeaninternal.api.SpiQuery;
 import io.ebeaninternal.api.SpiQuery.Type;
 import io.ebeaninternal.api.SpiSqlUpdate;
@@ -191,6 +192,8 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer {
 
   private final CurrentTenantProvider currentTenantProvider;
 
+  private final SpiLogManager logManager;
+
   /**
    * The default PersistenceContextScope used if it is not explicitly set on a query.
    */
@@ -231,6 +234,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer {
    */
   public DefaultServer(InternalConfiguration config, ServerCacheManager cache) {
 
+    this.logManager = config.getLogManager();
     this.dtoBeanManager = config.getDtoBeanManager();
     this.serverConfig = config.getServerConfig();
     this.objectGraphStats = new ConcurrentHashMap<>();
@@ -317,6 +321,11 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer {
     }
   }
 
+  @Override
+  public SpiLogManager log() {
+    return logManager;
+  }
+
   @Override
   public boolean isCollectQueryOrigins() {
     return collectQueryOrigins;

src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java

@@ -20,6 +20,8 @@ import io.ebean.plugin.SpiServer;
 import io.ebeaninternal.api.SpiBackgroundExecutor;
 import io.ebeaninternal.api.SpiEbeanServer;
 import io.ebeaninternal.api.SpiJsonContext;
+import io.ebeaninternal.api.SpiLogManager;
+import io.ebeaninternal.api.SpiLogger;
 import io.ebeaninternal.api.SpiProfileHandler;
 import io.ebeaninternal.dbmigration.DbOffline;
 import io.ebeaninternal.server.autotune.AutoTuneService;
@@ -44,6 +46,8 @@ import io.ebeaninternal.server.dto.DtoBeanManager;
 import io.ebeaninternal.server.expression.DefaultExpressionFactory;
 import io.ebeaninternal.server.expression.platform.DbExpressionHandler;
 import io.ebeaninternal.server.expression.platform.DbExpressionHandlerFactory;
+import io.ebeaninternal.server.log.DLogManager;
+import io.ebeaninternal.server.log.DSpiLogger;
 import io.ebeaninternal.server.persist.Binder;
 import io.ebeaninternal.server.persist.DefaultPersister;
 import io.ebeaninternal.server.persist.platform.MultiValueBind;
@@ -134,10 +138,13 @@ public class InternalConfiguration {
 
   private final MultiValueBind multiValueBind;
 
+  private final SpiLogManager logManager;
+
   public InternalConfiguration(ClusterManager clusterManager,
                                SpiCacheManager cacheManager, SpiBackgroundExecutor backgroundExecutor,
                                ServerConfig serverConfig, BootupClasses bootupClasses) {
 
+    this.logManager = initLogManager();
     this.docStoreFactory = initDocStoreFactory(serverConfig.service(DocStoreFactory.class));
     this.jsonFactory = serverConfig.getJsonFactory();
     this.clusterManager = clusterManager;
@@ -169,6 +176,18 @@ public class InternalConfiguration {
     this.cQueryEngine = new CQueryEngine(serverConfig, databasePlatform, binder, asOfTableMapping, draftTableMap);
   }
 
+  private SpiLogManager initLogManager() {
+
+    SpiLogger sql = logger("io.ebean.SQL");
+    SpiLogger sum = logger("io.ebean.SUM");
+    SpiLogger txn = logger("io.ebean.TXN");
+    return new DLogManager(sql, sum, txn);
+  }
+
+  private DSpiLogger logger(String name) {
+    return new DSpiLogger(LoggerFactory.getLogger(name));
+  }
+
   /**
    * Create and return the ExpressionFactory based on configuration and database platform.
    */
@@ -262,9 +281,9 @@ public class InternalConfiguration {
 
     DbHistorySupport historySupport = databasePlatform.getHistorySupport();
     if (historySupport == null) {
-      return new Binder(typeManager, 0, false, jsonHandler, dataTimeZone, multiValueBind);
+      return new Binder(typeManager, logManager, 0, false, jsonHandler, dataTimeZone, multiValueBind);
     }
-    return new Binder(typeManager, historySupport.getBindCount(), historySupport.isStandardsBased(), jsonHandler, dataTimeZone, multiValueBind);
+    return new Binder(typeManager, logManager, historySupport.getBindCount(), historySupport.isStandardsBased(), jsonHandler, dataTimeZone, multiValueBind);
   }
 
   /**
@@ -378,7 +397,7 @@ public class InternalConfiguration {
 
     TransactionManagerOptions options =
       new TransactionManagerOptions(notifyL2CacheInForeground, serverConfig, scopeManager, clusterManager, backgroundExecutor,
-                                    indexUpdateProcessor, beanDescriptorManager, dataSource(), profileHandler());
+                                    indexUpdateProcessor, beanDescriptorManager, dataSource(), profileHandler(), logManager);
 
     if (serverConfig.isExplicitTransactionBeginMode()) {
       return new ExplicitTransactionManager(options);
@@ -511,4 +530,8 @@ public class InternalConfiguration {
   public DtoBeanManager getDtoBeanManager() {
     return dtoBeanManager;
   }
+
+  public SpiLogManager getLogManager() {
+    return logManager;
+  }
 }

src/main/java/io/ebeaninternal/server/persist/Binder.java

@@ -2,11 +2,11 @@ package io.ebeaninternal.server.persist;
 
 import io.ebean.config.dbplatform.DbPlatformType;
 import io.ebeaninternal.api.BindParams;
+import io.ebeaninternal.api.SpiLogManager;
 import io.ebeaninternal.server.core.Message;
 import io.ebeaninternal.server.core.timezone.DataTimeZone;
 import io.ebeaninternal.server.expression.platform.DbExpressionHandler;
 import io.ebeaninternal.server.persist.platform.MultiValueBind;
-import io.ebeaninternal.server.transaction.TransactionManager;
 import io.ebeaninternal.server.type.DataBind;
 import io.ebeaninternal.server.type.ScalarType;
 import io.ebeaninternal.server.type.TypeManager;
@@ -48,7 +48,7 @@ public class Binder {
   /**
    * Set the PreparedStatement with which to bind variables to.
    */
-  public Binder(TypeManager typeManager, int asOfBindCount, boolean asOfStandardsBased,
+  public Binder(TypeManager typeManager, SpiLogManager logManager, int asOfBindCount, boolean asOfStandardsBased,
                 DbExpressionHandler dbExpressionHandler, DataTimeZone dataTimeZone, MultiValueBind multiValueBind) {
 
     this.typeManager = typeManager;
@@ -57,12 +57,7 @@ public class Binder {
     this.dbExpressionHandler = dbExpressionHandler;
     this.dataTimeZone = dataTimeZone;
     this.multiValueBind = multiValueBind;
-    this.enableBindLog = enableBindLog();
-  }
-
-  private boolean enableBindLog() {
-    return TransactionManager.SQL_LOGGER.isDebugEnabled()
-      || TransactionManager.SUM_LOGGER.isDebugEnabled();
+    this.enableBindLog = logManager.sql().isDebug();
   }
 
   /**

src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java

@@ -154,9 +154,7 @@ public abstract class DmlHandler implements PersistHandler, BindableRequest {
    */
   protected void logSql(String sql) {
     if (logLevelSql) {
-      if (TransactionManager.SQL_LOGGER.isTraceEnabled()) {
-        sql = Str.add(sql, "; --bind(", bindLog.toString(), ")");
-      }
+      sql = Str.add(sql, "; --bind(", bindLog.toString(), ")");
       transaction.logSql(sql);
     }
   }

src/main/java/io/ebeaninternal/server/query/CQueryEngine.java

@@ -82,9 +82,7 @@ public class CQueryEngine {
 
       if (request.isLogSql()) {
         String logSql = query.getGeneratedSql();
-        if (TransactionManager.SQL_LOGGER.isTraceEnabled()) {
-          logSql = Str.add(logSql, "; --bind(", query.getBindLog(), ") rows:", String.valueOf(rows));
-        }
+        logSql = Str.add(logSql, "; --bind(", query.getBindLog(), ") rows:", String.valueOf(rows));
         request.logSql(logSql);
       }
 
@@ -151,11 +149,7 @@ public class CQueryEngine {
   }
 
   private <T> void logGeneratedSql(OrmQueryRequest<T> request, String sql, String bindLog) {
-    String logSql = sql;
-    if (TransactionManager.SQL_LOGGER.isTraceEnabled()) {
-      logSql = Str.add(logSql, "; --bind(", bindLog, ")");
-    }
-    request.logSql(logSql);
+    request.logSql(Str.add(sql, "; --bind(", bindLog, ")"));
   }
 
   /**
@@ -458,9 +452,7 @@ public class CQueryEngine {
   private void logSql(CQuery<?> query) {
 
     String sql = query.getGeneratedSql();
-    if (TransactionManager.SQL_LOGGER.isTraceEnabled()) {
-      sql = Str.add(sql, "; --bind(", query.getBindLog(), ")");
-    }
+    sql = Str.add(sql, "; --bind(", query.getBindLog(), ")");
     query.getTransaction().logSql(sql);
   }
 

src/main/java/io/ebeaninternal/server/transaction/ImplicitReadOnlyTransaction.java

@@ -43,6 +43,9 @@ class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEventCode
 
   private final TransactionManager manager;
 
+  private final boolean logSql;
+  private final boolean logSummary;
+
   /**
    * The status of the transaction.
    */
@@ -70,6 +73,8 @@ class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEventCode
    */
   ImplicitReadOnlyTransaction(TransactionManager manager, Connection connection) {
     this.manager = manager;
+    this.logSql = manager.isLogSql();
+    this.logSummary = manager.isLogSummary();
     this.active = true;
     this.connection = connection;
     this.persistenceContext = new DefaultPersistenceContext();
@@ -441,22 +446,22 @@ class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEventCode
 
   @Override
   public boolean isLogSql() {
-    return TransactionManager.SQL_LOGGER.isDebugEnabled();
+    return logSql;
   }
 
   @Override
   public boolean isLogSummary() {
-    return TransactionManager.SUM_LOGGER.isDebugEnabled();
+    return logSummary;
   }
 
   @Override
   public void logSql(String msg) {
-    TransactionManager.SQL_LOGGER.debug(msg);
+    manager.log().sql().debug(msg);
   }
 
   @Override
   public void logSummary(String msg) {
-    TransactionManager.SUM_LOGGER.debug(msg);
+    manager.log().sum().debug(msg);
   }
 
   /**

src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java

@@ -55,6 +55,9 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
    */
   protected final String id;
 
+  private final boolean logSql;
+  private final boolean logSummary;
+
   /**
    * The user defined label to group execution statistics.
    */
@@ -200,11 +203,15 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
       this.startNanos = System.nanoTime();
 
       if (manager == null) {
+        this.logSql = false;
+        this.logSummary = false;
         this.skipCacheAfterWrite = true;
         this.batchMode = PersistBatch.NONE;
         this.batchOnCascadeMode = PersistBatch.NONE;
         this.onQueryOnly = OnQueryOnly.ROLLBACK;
       } else {
+        this.logSql = manager.isLogSql();
+        this.logSummary = manager.isLogSummary();
         this.skipCacheAfterWrite = manager.isSkipCacheAfterWrite();
         this.batchMode = manager.getPersistBatch();
         this.batchOnCascadeMode = manager.getPersistBatchOnCascade();
@@ -861,22 +868,22 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
 
   @Override
   public boolean isLogSql() {
-    return TransactionManager.SQL_LOGGER.isDebugEnabled();
+    return logSql;
   }
 
   @Override
   public boolean isLogSummary() {
-    return TransactionManager.SUM_LOGGER.isDebugEnabled();
+    return logSummary;
   }
 
   @Override
   public void logSql(String msg) {
-    TransactionManager.SQL_LOGGER.debug(Str.add(logPrefix, msg));
+    manager.log().sql().debug(Str.add(logPrefix, msg));
   }
 
   @Override
   public void logSummary(String msg) {
-    TransactionManager.SUM_LOGGER.debug(Str.add(logPrefix, msg));
+    manager.log().sum().debug(Str.add(logPrefix, msg));
   }
 
   /**

src/main/java/io/ebeaninternal/server/transaction/SavepointTransaction.java

@@ -21,6 +21,7 @@ class SavepointTransaction extends SpiTransactionProxy {
   private final Savepoint savepoint;
   private final Connection connection;
   private final String logPrefix;
+  private final String spPrefix;
 
   private boolean rollbackOnly;
   private int state;
@@ -31,7 +32,8 @@ class SavepointTransaction extends SpiTransactionProxy {
     this.connection = transaction.getInternalConnection();
     this.savepoint = connection.setSavepoint();
     int savepointId = savepoint.getSavepointId();
-    this.logPrefix = "txn[" + transaction.getId() + "-sp" + savepointId + "] ";
+    this.spPrefix = "sp[" + savepointId + "] ";
+    this.logPrefix = transaction.getLogPrefix() + spPrefix;
   }
 
   @Override
@@ -41,12 +43,12 @@ class SavepointTransaction extends SpiTransactionProxy {
 
   @Override
   public void logSql(String msg) {
-    TransactionManager.SQL_LOGGER.debug(Str.add(logPrefix, msg));
+    transaction.logSql(Str.add(spPrefix, msg));
   }
 
   @Override
   public void logSummary(String msg) {
-    TransactionManager.SUM_LOGGER.debug(Str.add(logPrefix, msg));
+    transaction.logSummary(Str.add(spPrefix, msg));
   }
 
   @Override

src/main/java/io/ebeaninternal/server/transaction/TransactionFactory.java

@@ -2,7 +2,6 @@ package io.ebeaninternal.server.transaction;
 
 import io.ebean.util.JdbcClose;
 import io.ebeaninternal.api.SpiTransaction;
-import org.slf4j.Logger;
 
 import javax.persistence.PersistenceException;
 import java.sql.Connection;
@@ -14,8 +13,6 @@ import java.util.concurrent.atomic.AtomicLong;
  */
 abstract class TransactionFactory {
 
-  static final Logger TXN_LOGGER = TransactionManager.TXN_LOGGER;
-
   final AtomicLong counter = new AtomicLong(1000);
 
   final TransactionManager manager;
@@ -51,8 +48,8 @@ abstract class TransactionFactory {
       }
     }
 
-    if (explicit && TXN_LOGGER.isTraceEnabled()) {
-      TXN_LOGGER.trace(t.getLogPrefix() + "Begin");
+    if (explicit && manager.log().txn().isTrace()) {
+      manager.log().txn().trace(t.getLogPrefix() + "Begin");
     }
 
     return t;

src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java

@@ -15,6 +15,8 @@ import io.ebean.meta.MetricType;
 import io.ebean.meta.MetricVisitor;
 import io.ebeaninternal.api.ScopeTrans;
 import io.ebeaninternal.api.ScopedTransaction;
+import io.ebeaninternal.api.SpiLogManager;
+import io.ebeaninternal.api.SpiLogger;
 import io.ebeaninternal.api.SpiProfileHandler;
 import io.ebeaninternal.api.SpiTransaction;
 import io.ebeaninternal.api.SpiTransactionManager;
@@ -53,12 +55,6 @@ public class TransactionManager implements SpiTransactionManager {
 
   public static final Logger clusterLogger = LoggerFactory.getLogger("io.ebean.Cluster");
 
-  public static final Logger SQL_LOGGER = LoggerFactory.getLogger("io.ebean.SQL");
-
-  public static final Logger SUM_LOGGER = LoggerFactory.getLogger("io.ebean.SUM");
-
-  public static final Logger TXN_LOGGER = LoggerFactory.getLogger("io.ebean.TXN");
-
   protected final BeanDescriptorManager beanDescriptorManager;
 
   /**
@@ -128,6 +124,9 @@ public class TransactionManager implements SpiTransactionManager {
 
   private final TransactionFactory transactionFactory;
 
+  private final SpiLogManager logManager;
+  private final SpiLogger txnLogger;
+
   private final DatabasePlatform databasePlatform;
 
   private final SpiProfileHandler profileHandler;
@@ -142,6 +141,8 @@ public class TransactionManager implements SpiTransactionManager {
    */
   public TransactionManager(TransactionManagerOptions options) {
 
+    this.logManager = options.logManager;
+    this.txnLogger = logManager.txn();
     this.databasePlatform = options.config.getDatabasePlatform();
     this.skipCacheAfterWrite = options.config.isSkipCacheAfterWrite();
     this.notifyL2CacheInForeground = options.notifyL2CacheInForeground;
@@ -355,12 +356,12 @@ public class TransactionManager implements SpiTransactionManager {
   public void notifyOfRollback(SpiTransaction transaction, Throwable cause) {
 
     try {
-      if (TXN_LOGGER.isDebugEnabled()) {
+      if (txnLogger.isDebug()) {
         String msg = transaction.getLogPrefix() + "Rollback";
         if (cause != null) {
           msg += " error: " + formatThrowable(cause);
         }
-        TXN_LOGGER.debug(msg);
+        txnLogger.debug(msg);
       }
 
     } catch (Exception ex) {
@@ -374,8 +375,8 @@ public class TransactionManager implements SpiTransactionManager {
   public void notifyOfQueryOnly(SpiTransaction transaction) {
 
     // Nothing that interesting here
-    if (TXN_LOGGER.isTraceEnabled()) {
-      TXN_LOGGER.trace(transaction.getLogPrefix() + "Commit - query only");
+    if (txnLogger.isTrace()) {
+      txnLogger.trace(transaction.getLogPrefix() + "Commit - query only");
     }
   }
 
@@ -409,8 +410,8 @@ public class TransactionManager implements SpiTransactionManager {
   public void notifyOfCommit(SpiTransaction transaction) {
 
     try {
-      if (TXN_LOGGER.isDebugEnabled()) {
-        TXN_LOGGER.debug(transaction.getLogPrefix() + "Commit");
+      if (txnLogger.isDebug()) {
+        txnLogger.debug(transaction.getLogPrefix() + "Commit");
       }
 
       PostCommitProcessing postCommit = new PostCommitProcessing(clusterManager, this, transaction);
@@ -702,4 +703,16 @@ public class TransactionManager implements SpiTransactionManager {
         throw new RuntimeException("Should never get here?");
     }
   }
+
+  public SpiLogManager log() {
+    return logManager;
+  }
+
+  public boolean isLogSql() {
+    return logManager.sql().isDebug();
+  }
+
+  public boolean isLogSummary() {
+    return logManager.sum().isDebug();
+  }
 }

src/main/java/io/ebeaninternal/server/transaction/TransactionManagerOptions.java

@@ -2,6 +2,7 @@ package io.ebeaninternal.server.transaction;
 
 import io.ebean.BackgroundExecutor;
 import io.ebean.config.ServerConfig;
+import io.ebeaninternal.api.SpiLogManager;
 import io.ebeaninternal.api.SpiProfileHandler;
 import io.ebeaninternal.server.cluster.ClusterManager;
 import io.ebeaninternal.server.deploy.BeanDescriptorManager;
@@ -22,10 +23,11 @@ public class TransactionManagerOptions {
   final DataSourceSupplier dataSourceSupplier;
   final SpiProfileHandler profileHandler;
   final TransactionScopeManager scopeManager;
+  final SpiLogManager logManager;
 
   public TransactionManagerOptions(boolean notifyL2CacheInForeground, ServerConfig config, TransactionScopeManager scopeManager, ClusterManager clusterManager,
                                    BackgroundExecutor backgroundExecutor, DocStoreUpdateProcessor docStoreUpdateProcessor,
-                                   BeanDescriptorManager descMgr, DataSourceSupplier dataSourceSupplier, SpiProfileHandler profileHandler) {
+                                   BeanDescriptorManager descMgr, DataSourceSupplier dataSourceSupplier, SpiProfileHandler profileHandler, SpiLogManager logManager) {
 
     this.notifyL2CacheInForeground = notifyL2CacheInForeground;
     this.config = config;
@@ -36,6 +38,7 @@ public class TransactionManagerOptions {
     this.descMgr = descMgr;
     this.dataSourceSupplier = dataSourceSupplier;
     this.profileHandler = profileHandler;
+    this.logManager = logManager;
   }
 
 }