Merge pull request #2912 from ebean-orm/wip/spi-txn-logging

Refactoring SpiLogger to better support conditional logging
This commit is contained in:
Rob Bygrave
2023-02-14 15:03:47 +13:00
committed by GitHub
37 changed files with 327 additions and 277 deletions
@@ -10,18 +10,25 @@ package io.ebeaninternal.api;
public interface SpiLogManager {
/**
* Return the SQL logger.
* Enable bind logging.
*/
boolean enableBindLog();
/**
* Logger used for general transactions.
*/
SpiTxnLogger logger();
/**
* Logger used for read only transactions.
*/
SpiTxnLogger readOnlyLogger();
/**
* Hmmmm, return the SQL logger for logging truncate statements.
* <p>
* Maybe we should get rid of this
*/
SpiLogger sql();
/**
* Return the TXN logger.
*/
SpiLogger txn();
/**
* Return the Summary logger.
*/
SpiLogger sum();
}
@@ -14,18 +14,9 @@ public interface SpiLogger {
*/
boolean isDebug();
/**
* Is trace logging enabled.
*/
boolean isTrace();
/**
* Log a debug level message.
*/
void debug(String msg);
void debug(String msg, Object... args);
/**
* Log a trace level message.
*/
void trace(String msg);
}
@@ -27,10 +27,6 @@ public interface SpiTransaction extends Transaction {
*/
String getLabel();
/**
* Return the string prefix with the transaction id and label used in logging.
*/
String getLogPrefix();
/**
* Return true if generated SQL and Bind values should be logged to the
@@ -47,12 +43,17 @@ public interface SpiTransaction extends Transaction {
/**
* Log a message to the SQL logger.
*/
void logSql(String msg);
void logSql(String msg, Object... args);
/**
* Log a message to the SUMMARY logger.
* Log a summary message to the SUMMARY logger.
*/
void logSummary(String msg);
void logSummary(String msg, Object... args);
/**
* Log a transaction message to the transaction logger.
*/
void logTxn(String msg, Object... args);
/**
* Register a "Deferred Relationship" that requires an additional update later.
@@ -137,10 +137,6 @@ public abstract class SpiTransactionProxy implements SpiTransaction {
transaction.setDocStoreBatchSize(batchSize);
}
@Override
public String getLogPrefix() {
return transaction.getLogPrefix();
}
@Override
public boolean isLogSql() {
@@ -153,13 +149,18 @@ public abstract class SpiTransactionProxy implements SpiTransaction {
}
@Override
public void logSql(String msg) {
transaction.logSql(msg);
public void logSql(String msg, Object... args) {
transaction.logSql(msg, args);
}
@Override
public void logSummary(String msg) {
transaction.logSummary(msg);
public void logSummary(String msg, Object... args) {
transaction.logSummary(msg, args);
}
@Override
public void logTxn(String msg, Object... args) {
transaction.logTxn(msg, args);
}
@Override
@@ -0,0 +1,49 @@
package io.ebeaninternal.api;
/**
* Per Transaction logging of SQL, TXN and Summary messages.
*/
public interface SpiTxnLogger {
String id();
/**
* Is debug logging enabled.
*/
boolean isLogSql();
/**
* Is summary logging enabled.
*/
boolean isLogSummary();
/**
* Log a SQL message.
*/
void sql(String msg, Object... args);
/**
* Log a Summary message.
*/
void sum(String msg, Object... args);
/**
* Log a Transaction message.
*/
void txn(String msg, Object... args);
/**
* Transaction Committed.
*/
void notifyCommit();
/**
* Query only transaction completed.
*/
void notifyQueryOnly();
/**
* Transaction Rolled back.
*/
void notifyRollback(Throwable cause);
}
@@ -4,7 +4,6 @@ import io.ebean.CancelableQuery;
import io.ebean.Transaction;
import io.ebean.util.JdbcClose;
import io.ebeaninternal.api.*;
import io.ebeaninternal.server.util.Str;
import io.ebeaninternal.server.persist.Binder;
import io.ebeaninternal.server.persist.TrimLogSql;
import io.ebeaninternal.server.util.BindParamsParser;
@@ -151,7 +150,7 @@ public abstract class AbstractSqlQueryRequest implements CancelableQuery {
}
if (isLogSql()) {
long micros = (System.nanoTime() - startNano) / 1000L;
transaction.logSql(Str.add(TrimLogSql.trim(sql), "; --bind(", bindLog, ") --micros(", micros + ")"));
transaction.logSql("{0}; --bind({1}) --micros({2})", TrimLogSql.trim(sql), bindLog, micros);
}
} finally {
lock.unlock();
@@ -701,8 +701,8 @@ public final class OrmQueryRequest<T> extends BeanRequest implements SpiOrmQuery
/**
* Log the SQL if the logLevel is appropriate.
*/
public void logSql(String sql) {
transaction.logSql(sql);
public void logSql(String msg, Object... args) {
transaction.logSql(msg, args);
}
/**
@@ -928,20 +928,20 @@ public final class PersistRequestBean<T> extends PersistRequest implements BeanP
}
private void logSummaryMessage() {
String draft = (beanDescriptor.isDraftable() && !publish) ? "] draft[true]" : "]";
String draft = (beanDescriptor.isDraftable() && !publish) ? " draft[true]" : "";
String name = beanDescriptor.name();
switch (type) {
case INSERT:
transaction.logSummary("Inserted [" + name + "] [" + (idValue == null ? "" : idValue) + draft);
transaction.logSummary("Inserted [{0}] [{1}]{2}", name, (idValue == null ? "" : idValue), draft);
break;
case UPDATE:
transaction.logSummary("Updated [" + name + "] [" + idValue + draft);
transaction.logSummary("Updated [{0}] [{1}]{2}", name, idValue , draft);
break;
case DELETE:
transaction.logSummary("Deleted [" + name + "] [" + idValue + draft);
transaction.logSummary("Deleted [{0}] [{1}]{2}", name, idValue , draft);
break;
case DELETE_SOFT:
transaction.logSummary("SoftDelete [" + name + "] [" + idValue + draft);
transaction.logSummary("SoftDelete [{0}] [{1}]{2}", name, idValue , draft);
break;
default:
break;
@@ -1,12 +1,8 @@
package io.ebeaninternal.server.core;
import io.ebean.CallableSql;
import io.ebeaninternal.api.BindParams;
import io.ebeaninternal.api.*;
import io.ebeaninternal.api.BindParams.Param;
import io.ebeaninternal.api.SpiCallableSql;
import io.ebeaninternal.api.SpiEbeanServer;
import io.ebeaninternal.api.SpiTransaction;
import io.ebeaninternal.api.TransactionEventTable;
import io.ebeaninternal.server.persist.PersistExecute;
import java.sql.CallableStatement;
@@ -86,7 +82,7 @@ public final class PersistRequestCallableSql extends PersistRequest {
persistExecute.collectSqlCall(label, startNanos);
}
if (transaction.isLogSummary()) {
transaction.logSummary("CallableSql label[" + callableSql.getLabel() + "]" + " rows[" + rowCount + "]" + " bind[" + bindLog + "]");
transaction.logSummary("CallableSql label[{0}] rows[{1}] bind[{2}]", callableSql.getLabel(), rowCount, bindLog);
}
// register table modifications with the transaction event
@@ -83,7 +83,7 @@ public final class PersistRequestOrmUpdate extends PersistRequest {
OrmUpdateType ormUpdateType = ormUpdate.getOrmUpdateType();
String tableName = ormUpdate.getBaseTable();
if (transaction.isLogSummary()) {
transaction.logSummary(ormUpdateType + " table[" + tableName + "] rows[" + rowCount + "] bind[" + bindLog + "]");
transaction.logSummary("{0} table[{1}] rows[{2}] bind[{3}]", ormUpdateType, tableName, rowCount, bindLog);
}
if (ormUpdate.isNotifyCache()) {
// add the modification info to the TransactionEvent
@@ -3,7 +3,6 @@ package io.ebeaninternal.server.core;
import io.ebeaninternal.api.SpiEbeanServer;
import io.ebeaninternal.api.SpiSqlUpdate;
import io.ebeaninternal.api.SpiTransaction;
import io.ebeaninternal.server.util.Str;
import io.ebeaninternal.server.persist.BatchControl;
import io.ebeaninternal.server.persist.PersistExecute;
import io.ebeaninternal.server.persist.TrimLogSql;
@@ -148,7 +147,7 @@ public final class PersistRequestUpdateSql extends PersistRequest {
*/
public void logSqlBatchBind() {
if (transaction.isLogSql()) {
transaction.logSql(Str.add(" -- bind(", bindLog, ")"));
transaction.logSql(" -- bind({0})", bindLog);
}
}
@@ -161,7 +160,7 @@ public final class PersistRequestUpdateSql extends PersistRequest {
persistExecute.collectSqlUpdate(label, startNanos);
}
if (transaction.isLogSql() && !batchThisRequest) {
transaction.logSql(Str.add(TrimLogSql.trim(updateSql.getGeneratedSql()), "; -- bind(", bindLog, ") rows(", String.valueOf(rowCount), ")"));
transaction.logSql("{0}; -- bind({1}) rows({2})", TrimLogSql.trim(updateSql.getGeneratedSql()), bindLog, rowCount);
}
if (updateSql.isAutoTableMod()) {
// add the modification info to the TransactionEvent
@@ -123,7 +123,7 @@ public final class RelationalQueryRequest extends AbstractSqlQueryRequest {
public void logSummary() {
if (transaction.isLogSummary()) {
long micros = (System.nanoTime() - startNano) / 1000L;
transaction.logSummary("SqlQuery rows[" + rows + "] micros[" + micros + "] bind[" + bindLog + "]");
transaction.logSummary("SqlQuery rows[{0}] micros[{1}] bind[{2}]", rows, micros, bindLog);
}
}
@@ -2,22 +2,30 @@ package io.ebeaninternal.server.logger;
import io.ebeaninternal.api.SpiLogManager;
import io.ebeaninternal.api.SpiLogger;
import io.ebeaninternal.api.SpiTxnLogger;
import java.util.concurrent.atomic.AtomicLong;
public final class DLogManager implements SpiLogManager {
private final SpiLogger sql;
private final SpiLogger summary;
private final SpiLogger txn;
private final boolean useIds;
private final AtomicLong counter = new AtomicLong(1000);
private final DTxnLogger readOnly;
public DLogManager(SpiLogger sql, SpiLogger summary, SpiLogger txn) {
this.sql = sql;
this.summary = summary;
this.txn = txn;
this.useIds = txn.isDebug();
this.readOnly = new DTxnLogger(null, sql, summary, txn);
}
@Override
public SpiLogger txn() {
return txn;
public boolean enableBindLog() {
return sql.isDebug();
}
@Override
@@ -26,8 +34,13 @@ public final class DLogManager implements SpiLogManager {
}
@Override
public SpiLogger sum() {
return summary;
public SpiTxnLogger logger() {
String id = useIds ? Long.toString(counter.incrementAndGet()) : "";
return new DTxnLogger(id, sql, summary, txn);
}
@Override
public SpiTxnLogger readOnlyLogger() {
return readOnly;
}
}
@@ -3,7 +3,6 @@ package io.ebeaninternal.server.logger;
import io.ebeaninternal.api.SpiLogger;
import static java.lang.System.Logger.Level.DEBUG;
import static java.lang.System.Logger.Level.TRACE;
final class DSpiLogger implements SpiLogger {
@@ -19,17 +18,7 @@ final class DSpiLogger implements SpiLogger {
}
@Override
public boolean isTrace() {
return logger.isLoggable(TRACE);
}
@Override
public void debug(String msg) {
logger.log(DEBUG, msg);
}
@Override
public void trace(String msg) {
logger.log(TRACE, msg);
public void debug(String msg, Object... args) {
logger.log(DEBUG, msg, args);
}
}
@@ -0,0 +1,96 @@
package io.ebeaninternal.server.logger;
import io.ebeaninternal.api.SpiLogger;
import io.ebeaninternal.api.SpiTxnLogger;
import io.ebeaninternal.server.util.Str;
final class DTxnLogger implements SpiTxnLogger {
private final String id;
private final String logPrefix;
private final SpiLogger sql;
private final SpiLogger sum;
private final SpiLogger txn;
DTxnLogger(String id, SpiLogger sql, SpiLogger sum, SpiLogger txn) {
this.id = id;
this.logPrefix = id == null ? "" : "txn[" + id + "] ";
this.sql = sql;
this.sum = sum;
this.txn = txn;
}
@Override
public String id() {
return id;
}
@Override
public boolean isLogSql() {
return sql.isDebug();
}
@Override
public boolean isLogSummary() {
return sum.isDebug();
}
@Override
public void sql(String msg, Object... args) {
sql.debug(Str.add(logPrefix, msg), args);
}
@Override
public void sum(String msg, Object... args) {
sum.debug(Str.add(logPrefix, msg), args);
}
@Override
public void txn(String msg, Object... args) {
txn.debug(Str.add(logPrefix, msg), args);
}
@Override
public void notifyCommit() {
txn.debug(Str.add(logPrefix, "Commit"));
}
@Override
public void notifyQueryOnly() {
// do nothing
}
@Override
public void notifyRollback(Throwable cause) {
if (txn.isDebug()) {
String msg = logPrefix + "Rollback";
if (cause != null) {
msg += " error: " + formatThrowable(cause);
}
txn.debug(msg);
}
}
private String formatThrowable(Throwable e) {
if (e == null) {
return "";
}
StringBuilder sb = new StringBuilder();
formatThrowable(e, sb);
return sb.toString();
}
private void formatThrowable(Throwable e, StringBuilder sb) {
sb.append(e.toString());
StackTraceElement[] stackTrace = e.getStackTrace();
if (stackTrace.length > 0) {
sb.append(" stack0: ");
sb.append(stackTrace[0]);
}
Throwable cause = e.getCause();
if (cause != null) {
sb.append(" cause: ");
formatThrowable(cause, sb);
}
}
}
@@ -313,7 +313,7 @@ public final class BatchControl {
BatchedBeanHolder[] bsArray = beanHolderArray();
Arrays.sort(bsArray, depthComparator);
if (transaction.isLogSummary()) {
transaction.logSummary("BatchControl flush " + Arrays.toString(bsArray));
transaction.logSummary("BatchControl flush {0}", Arrays.toString(bsArray));
}
for (BatchedBeanHolder beanHolder : bsArray) {
beanHolder.executeNow();
@@ -44,7 +44,7 @@ public final class Binder {
this.dbExpressionHandler = dbExpressionHandler;
this.dataTimeZone = dataTimeZone;
this.multiValueBind = multiValueBind;
this.enableBindLog = logManager.sql().isDebug();
this.enableBindLog = logManager.enableBindLog();
}
/**
@@ -672,7 +672,7 @@ public final class DefaultPersister implements Persister {
if (idList != null) {
q.where().idIn(idList);
if (t.isLogSummary()) {
t.logSummary("-- DeleteById of " + descriptor.name() + " ids[" + idList + "] requires fetch of foreign key values");
t.logSummary("-- DeleteById of {0} ids[{1}] requires fetch of foreign key values", descriptor.name(), idList);
}
List<?> beanList = server.findList(q, t);
deleteCascade(beanList, t, deleteMode, false);
@@ -681,7 +681,7 @@ public final class DefaultPersister implements Persister {
} else {
q.where().idEq(id);
if (t.isLogSummary()) {
t.logSummary("-- DeleteById of " + descriptor.name() + " id[" + id + "] requires fetch of foreign key values");
t.logSummary("-- DeleteById of {0} id[{1}] requires fetch of foreign key values", descriptor.name(), id);
}
EntityBean bean = (EntityBean) server.findOne(q, t);
if (bean == null) {
@@ -741,7 +741,7 @@ public final class DefaultPersister implements Persister {
for (BeanPropertyAssocMany<?> many : manys) {
SqlUpdate sqlDelete = many.deleteByParentId(id, idList);
if (t.isLogSummary()) {
t.logSummary("-- Deleting intersection table entries: " + many.fullName());
t.logSummary("-- Deleting intersection table entries: {0}", many.fullName());
}
executeSqlUpdate(sqlDelete, t);
}
@@ -751,9 +751,9 @@ public final class DefaultPersister implements Persister {
SqlUpdate deleteById = descriptor.deleteById(id, idList, deleteMode);
if (t.isLogSummary()) {
if (idList != null) {
t.logSummary("-- Deleting " + descriptor.name() + " Ids: " + idList);
t.logSummary("-- Deleting {0} Ids: {1}", descriptor.name(), idList);
} else {
t.logSummary("-- Deleting " + descriptor.name() + " Id: " + id);
t.logSummary("-- Deleting {0} Id: {1}", descriptor.name(), id);
}
}
@@ -69,7 +69,7 @@ final class DeleteUnloadedForeignKeys {
SpiTransaction t = request.transaction();
if (t.isLogSummary()) {
t.logSummary("-- Ebean fetching foreign key values for delete of " + descriptor.name() + " id:" + id);
t.logSummary("-- Ebean fetching foreign key values for delete of {0} id:{1}", descriptor.name(), id);
}
beanWithForeignKeys = (EntityBean) server.findOne(q, t);
}
@@ -8,7 +8,6 @@ import io.ebeaninternal.server.persist.BatchedPstmt;
import io.ebeaninternal.server.persist.BatchedPstmtHolder;
import io.ebeaninternal.server.persist.dmlbind.BindableRequest;
import io.ebeaninternal.server.bind.DataBind;
import io.ebeaninternal.server.util.Str;
import javax.persistence.OptimisticLockException;
import java.sql.Connection;
@@ -102,7 +101,7 @@ public abstract class DmlHandler implements PersistHandler, BindableRequest {
} catch (OptimisticLockException e) {
// add the SQL and bind values to error message
final String m = e.getMessage() + " sql[" + sql + "] bind[" + bindLog + "]";
persistRequest.transaction().logSummary("OptimisticLockException:" + m);
persistRequest.transaction().logSummary("OptimisticLockException:{0}", m);
throw new OptimisticLockException(m, null, e.getEntity());
}
}
@@ -146,15 +145,15 @@ public abstract class DmlHandler implements PersistHandler, BindableRequest {
switch (batchedStatus) {
case BATCHED_FIRST: {
transaction.logSql(sql);
transaction.logSql(Str.add(" -- bind(", bindLog.toString(), ")"));
transaction.logSql(" -- bind({0})", bindLog);
return;
}
case BATCHED: {
transaction.logSql(Str.add(" -- bind(", bindLog.toString(), ")"));
transaction.logSql(" -- bind({0})", bindLog);
return;
}
default: {
transaction.logSql(Str.add(sql, "; -- bind(", bindLog.toString(), ")"));
transaction.logSql("{0}; -- bind({1})", sql, bindLog);
}
}
}
@@ -18,7 +18,6 @@ import io.ebeaninternal.server.core.OrmQueryRequest;
import io.ebeaninternal.server.core.SpiResultSet;
import io.ebeaninternal.server.deploy.BeanDescriptor;
import io.ebeaninternal.server.persist.Binder;
import io.ebeaninternal.server.util.Str;
import javax.persistence.PersistenceException;
import java.sql.ResultSet;
@@ -73,7 +72,7 @@ public final class CQueryEngine {
try {
int rows = query.execute();
if (request.logSql()) {
request.logSql(Str.add(query.generatedSql(), "; --bind(", query.bindLog(), ") --micros(", query.micros() + ") --rows(", rows + ")"));
request.logSql("{0}; --bind({1}) --micros({2}) --rows({3})", query.generatedSql(), query.bindLog(), query.micros(), rows);
}
return rows;
} catch (SQLException e) {
@@ -129,7 +128,7 @@ public final class CQueryEngine {
SpiTransaction t = request.transaction();
if (t.isLogSummary()) {
// log the error to the transaction log
t.logSummary("ERROR executing query, bindLog[" + bindLog + "] error:" + StringHelper.removeNewLines(e.getMessage()));
t.logSummary("ERROR executing query, bindLog[{0}] error:{1}", bindLog, StringHelper.removeNewLines(e.getMessage()));
}
// ensure 'rollback' is logged if queryOnly transaction
t.connection();
@@ -147,7 +146,7 @@ public final class CQueryEngine {
}
private <T> void logGeneratedSql(OrmQueryRequest<T> request, String sql, String bindLog, long micros) {
request.logSql(Str.add(sql, "; --bind(", bindLog, ") --micros(", micros + ")"));
request.logSql("{0}; --bind({1}) --micros({2})", sql, bindLog, micros);
}
/**
@@ -403,7 +402,7 @@ public final class CQueryEngine {
* Log the generated SQL to the transaction log.
*/
private void logSql(CQuery<?> query) {
query.transaction().logSql(Str.add(query.generatedSql(), "; --bind(", query.bindLog(), ") --micros(", query.micros() + ")"));
query.transaction().logSql("{0}; --bind({1}) --micros({2})", query.generatedSql(), query.bindLog(), query.micros());
}
/**
@@ -10,8 +10,8 @@ public final class DocStoreOnlyTransaction extends JdbcTransaction {
/**
* Create a new DocStore only Transaction.
*/
public DocStoreOnlyTransaction(String id, boolean explicit, TransactionManager manager) {
super(id, explicit, null, manager);
public DocStoreOnlyTransaction(boolean explicit, TransactionManager manager) {
super(explicit, null, manager);
}
@Override
@@ -25,11 +25,11 @@ public final class DocStoreTransactionManager extends TransactionManager {
@Override
public SpiTransaction createReadOnlyTransaction(Object tenantId) {
return new DocStoreOnlyTransaction("", false, this);
return new DocStoreOnlyTransaction(false, this);
}
@Override
protected SpiTransaction createTransaction(boolean explicit, Connection c) {
return new DocStoreOnlyTransaction(nextTxnId(), explicit, this);
return new DocStoreOnlyTransaction(explicit, this);
}
}
@@ -25,14 +25,14 @@ public class ExternalJdbcTransaction extends JdbcTransaction {
* </p>
*/
public ExternalJdbcTransaction(Connection connection) {
super(null, true, connection, null);
super(true, connection, null);
}
/**
* Construct will all explicit parameters.
*/
public ExternalJdbcTransaction(String id, boolean explicit, Connection connection, TransactionManager manager) {
super(id, explicit, connection, manager);
public ExternalJdbcTransaction(boolean explicit, Connection connection, TransactionManager manager) {
super(explicit, connection, manager);
}
/**
@@ -33,6 +33,7 @@ final class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEve
private static final String notExpectedMessage = "Not expected on read only transaction";
private final TransactionManager manager;
private final SpiTxnLogger logger;
private final boolean logSql;
private final boolean logSummary;
@@ -61,8 +62,9 @@ final class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEve
*/
ImplicitReadOnlyTransaction(TransactionManager manager, Connection connection) {
this.manager = manager;
this.logSql = manager.isLogSql();
this.logSummary = manager.isLogSummary();
this.logger = manager.loggerReadOnly();
this.logSql = logger.isLogSql();
this.logSummary = logger.isLogSummary();
this.active = true;
this.connection = connection;
this.persistenceContext = new DefaultPersistenceContext();
@@ -147,11 +149,6 @@ final class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEve
public void setSkipCache(boolean skipCache) {
}
@Override
public String getLogPrefix() {
return null;
}
@Override
public void addBeanChange(BeanChange beanChange) {
throw new IllegalStateException(notExpectedMessage);
@@ -433,13 +430,18 @@ final class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEve
}
@Override
public void logSql(String msg) {
manager.log().sql().debug(msg);
public void logSql(String msg, Object... args) {
logger.sql(msg, args);
}
@Override
public void logSummary(String msg) {
manager.log().sum().debug(msg);
public void logSummary(String msg, Object... args) {
logger.sum(msg, args);
}
@Override
public void logTxn(String msg, Object... args) {
// never called
}
/**
@@ -11,7 +11,6 @@ import io.ebeaninternal.server.core.PersistDeferredRelationship;
import io.ebeaninternal.server.core.PersistRequestBean;
import io.ebeaninternal.server.persist.BatchControl;
import io.ebeaninternal.server.persist.BatchedSqlException;
import io.ebeaninternal.server.util.Str;
import io.ebeanservice.docstore.api.DocStoreTransaction;
import javax.persistence.PersistenceException;
@@ -33,8 +32,8 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
private static final String illegalStateMessage = "Transaction is Inactive";
final TransactionManager manager;
private final SpiTxnLogger logger;
private final String id;
private final String logPrefix;
private final boolean logSql;
private final boolean logSummary;
private final boolean explicit;
@@ -95,17 +94,17 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
private final long startNanos;
private boolean autoPersistUpdates;
JdbcTransaction(String id, boolean explicit, Connection connection, TransactionManager manager) {
JdbcTransaction(boolean explicit, Connection connection, TransactionManager manager) {
try {
this.active = true;
this.id = id;
this.logPrefix = deriveLogPrefix(id);
this.explicit = explicit;
this.manager = manager;
this.connection = connection;
this.persistenceContext = new DefaultPersistenceContext();
this.startNanos = System.nanoTime();
if (manager == null) {
this.logger = null;
this.id = "";
this.logSql = false;
this.logSummary = false;
this.skipCacheAfterWrite = true;
@@ -113,9 +112,11 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
this.batchOnCascadeMode = false;
this.onQueryOnlyCommit = false;
} else {
this.logger = manager.logger();
this.id = logger.id();
this.autoPersistUpdates = explicit && manager.isAutoPersistUpdates();
this.logSql = manager.isLogSql();
this.logSummary = manager.isLogSummary();
this.logSql = logger.isLogSql();
this.logSummary = logger.isLogSummary();
this.skipCacheAfterWrite = manager.isSkipCacheAfterWrite();
this.batchMode = manager.isPersistBatch();
this.batchOnCascadeMode = manager.isPersistBatchOnCascade();
@@ -188,16 +189,7 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
}
}
private static String deriveLogPrefix(String id) {
StringBuilder sb = new StringBuilder();
sb.append("txn[");
if (id != null) {
sb.append(id);
}
sb.append("] ");
return sb.toString();
}
@Override
public final void setAutoPersistUpdates(boolean autoPersistUpdates) {
@@ -226,17 +218,13 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
this.skipCache = skipCache;
}
@Override
public final String getLogPrefix() {
return logPrefix;
}
@Override
public String toString() {
if (active) {
return logPrefix;
return id;
} else {
return logPrefix + "(inactive)";
return id + "(inactive)";
}
}
@@ -726,13 +714,18 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
}
@Override
public final void logSql(String msg) {
manager.log().sql().debug(Str.add(logPrefix, msg));
public void logSql(String msg, Object... args) {
logger.sql(msg, args);
}
@Override
public final void logSummary(String msg) {
manager.log().sum().debug(Str.add(logPrefix, msg));
public final void logSummary(String msg, Object... args) {
logger.sum(msg, args);
}
@Override
public void logTxn(String msg, Object... args) {
logger.txn(msg, args);
}
/**
@@ -805,9 +798,11 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
final void notifyCommit() {
if (manager != null) {
if (queryOnly) {
logger.notifyQueryOnly();
manager.notifyOfQueryOnly(this);
} else {
manager.notifyOfCommit(this);
logger.notifyCommit();
}
}
}
@@ -966,6 +961,7 @@ class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
manager.notifyOfQueryOnly(this);
} else {
manager.notifyOfRollback(this, cause);
logger.notifyRollback(cause);
}
}
}
@@ -20,8 +20,8 @@ public final class JtaTransaction extends JdbcTransaction {
/**
* Create the JtaTransaction.
*/
public JtaTransaction(String id, boolean explicit, UserTransaction utx, DataSource ds, TransactionManager manager) {
super(id, explicit, null, manager);
public JtaTransaction(boolean explicit, UserTransaction utx, DataSource ds, TransactionManager manager) {
super(explicit, null, manager);
userTransaction = utx;
try {
newTransaction = userTransaction.getStatus() == Status.STATUS_NO_TRANSACTION;
@@ -105,8 +105,7 @@ public final class JtaTransactionManager implements ExternalTransactionManager {
// This is a transaction that Ebean has not seen before.
// "wrap" it in a Ebean specific JtaTransaction
String txnId = String.valueOf(System.currentTimeMillis());
JtaTransaction newTrans = new JtaTransaction(txnId, true, ut, dataSource(), transactionManager);
JtaTransaction newTrans = new JtaTransaction( true, ut, dataSource(), transactionManager);
// create and register transaction listener
JtaTxnListener txnListener = createJtaTxnListener(newTrans);
@@ -117,10 +117,6 @@ final class NoTransaction implements SpiTransaction {
// do nothing
}
@Override
public String getLogPrefix() {
return null;
}
@Override
public boolean isLogSql() {
@@ -133,12 +129,17 @@ final class NoTransaction implements SpiTransaction {
}
@Override
public void logSql(String msg) {
public void logSql(String msg, Object... args) {
}
@Override
public void logSummary(String msg) {
public void logSummary(String msg, Object... args) {
}
@Override
public void logTxn(String msg, Object... args) {
}
@@ -21,7 +21,6 @@ final class SavepointTransaction extends SpiTransactionProxy {
private final TransactionManager manager;
private final Savepoint savepoint;
private final Connection connection;
private final String logPrefix;
private final String spPrefix;
private boolean rollbackOnly;
@@ -33,13 +32,12 @@ final class SavepointTransaction extends SpiTransactionProxy {
this.transaction = transaction;
this.connection = transaction.getInternalConnection();
this.savepoint = connection.setSavepoint();
if (manager.isTxnDebug()) {
if (transaction.isLogSql()) {
int savepointId = manager.isSupportsSavepointId() ? savepoint.getSavepointId() : 0;
this.spPrefix = "sp[" + savepointId + "] ";
} else {
this.spPrefix = "sp[] ";
}
this.logPrefix = transaction.getLogPrefix() + spPrefix;
}
@Override
@@ -51,18 +49,13 @@ final class SavepointTransaction extends SpiTransactionProxy {
}
@Override
public String getLogPrefix() {
return logPrefix;
public void logSql(String msg, Object... args) {
transaction.logSql(Str.add(spPrefix, msg), args);
}
@Override
public void logSql(String msg) {
transaction.logSql(Str.add(spPrefix, msg));
}
@Override
public void logSummary(String msg) {
transaction.logSummary(Str.add(spPrefix, msg));
public void logSummary(String msg, Object... args) {
transaction.logSummary(Str.add(spPrefix, msg), args);
}
@Override
@@ -99,6 +92,7 @@ final class SavepointTransaction extends SpiTransactionProxy {
connection.releaseSavepoint(savepoint);
state = STATE_COMMITTED;
manager.notifyOfCommit(this);
transaction.logTxn(spPrefix + "commit");
} catch (SQLException e) {
throw new PersistenceException("Error trying to commit/release Savepoint", e);
}
@@ -109,6 +103,7 @@ final class SavepointTransaction extends SpiTransactionProxy {
connection.rollback(savepoint);
state = STATE_ROLLED_BACK;
manager.notifyOfRollback(this, cause);
transaction.logTxn(spPrefix + "rollback");//TODO: Pass the cause
} catch (SQLException e) {
throw new PersistenceException("Error trying to rollback Savepoint", e);
}
@@ -43,9 +43,6 @@ abstract class TransactionFactory {
throw new PersistenceException(e);
}
}
if (explicit && manager.log().txn().isTrace()) {
manager.log().txn().trace(t.getLogPrefix() + "Begin");
}
return t;
}
}
@@ -36,7 +36,6 @@ import java.sql.SQLException;
import java.util.List;
import java.util.Set;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.atomic.AtomicLong;
import static java.lang.System.Logger.Level.DEBUG;
import static java.lang.System.Logger.Level.ERROR;
@@ -63,8 +62,6 @@ public class TransactionManager implements SpiTransactionManager {
* Prefix for transaction id's (logging).
*/
final String prefix;
private final String externalTransPrefix;
private final AtomicLong counter = new AtomicLong(1000L);
/**
* The dataSource of connections.
@@ -96,8 +93,6 @@ public class TransactionManager implements SpiTransactionManager {
private final boolean skipCacheAfterWrite;
private final TransactionFactory transactionFactory;
private final SpiLogManager logManager;
private final SpiLogger txnLogger;
private final boolean txnDebug;
private final DatabasePlatform databasePlatform;
private final SpiProfileHandler profileHandler;
private final TimedMetric txnMain;
@@ -115,8 +110,6 @@ public class TransactionManager implements SpiTransactionManager {
public TransactionManager(TransactionManagerOptions options) {
this.server = options.server;
this.logManager = options.logManager;
this.txnLogger = logManager.txn();
this.txnDebug = txnLogger.isDebug();
this.databasePlatform = options.config.getDatabasePlatform();
this.supportsSavepointId = databasePlatform.supportsSavepointId();
this.skipCacheAfterWrite = options.config.isSkipCacheAfterWrite();
@@ -142,7 +135,6 @@ public class TransactionManager implements SpiTransactionManager {
this.profileHandler = options.profileHandler;
this.bulkEventListenerMap = new BulkEventListenerMap(options.config.getBulkTableEventListeners());
this.prefix = "";
this.externalTransPrefix = "e";
CurrentTenantProvider tenantProvider = options.config.getCurrentTenantProvider();
this.transactionFactory = TransactionFactoryBuilder.build(this, dataSourceSupplier, tenantProvider);
@@ -273,14 +265,7 @@ public class TransactionManager implements SpiTransactionManager {
* Wrap the externally supplied Connection.
*/
public SpiTransaction wrapExternalConnection(Connection c) {
return wrapExternalConnection(externalTransPrefix + c.hashCode(), c);
}
/**
* Wrap an externally supplied Connection with a known transaction id.
*/
private SpiTransaction wrapExternalConnection(String id, Connection c) {
ExternalJdbcTransaction t = new ExternalJdbcTransaction(id, true, c, this);
ExternalJdbcTransaction t = new ExternalJdbcTransaction(true, c, this);
// set the default batch mode
t.setBatchMode(persistBatch);
t.setBatchOnCascade(persistBatchOnCascade);
@@ -313,14 +298,7 @@ public class TransactionManager implements SpiTransactionManager {
* Create a new transaction.
*/
SpiTransaction createTransaction(boolean explicit, Connection c) {
return new JdbcTransaction(nextTxnId(), explicit, c, this);
}
/**
* Return the next transaction id.
*/
String nextTxnId() {
return txnDebug ? prefix + counter.incrementAndGet() : prefix;
return new JdbcTransaction(explicit, c, this);
}
/**
@@ -328,17 +306,7 @@ public class TransactionManager implements SpiTransactionManager {
*/
@Override
public final void notifyOfRollback(SpiTransaction transaction, Throwable cause) {
try {
if (txnLogger.isDebug()) {
String msg = transaction.getLogPrefix() + "Rollback";
if (cause != null) {
msg += " error: " + formatThrowable(cause);
}
txnLogger.debug(msg);
}
} catch (Exception ex) {
log.log(ERROR, "Error while notifying TransactionEventListener of rollback event", ex);
}
// Do nothing now
}
/**
@@ -347,32 +315,6 @@ public class TransactionManager implements SpiTransactionManager {
@Override
public final void notifyOfQueryOnly(SpiTransaction transaction) {
// Nothing that interesting here
if (txnLogger.isTrace()) {
txnLogger.trace(transaction.getLogPrefix() + "Commit - query only");
}
}
private String formatThrowable(Throwable e) {
if (e == null) {
return "";
}
StringBuilder sb = new StringBuilder();
formatThrowable(e, sb);
return sb.toString();
}
private void formatThrowable(Throwable e, StringBuilder sb) {
sb.append(e.toString());
StackTraceElement[] stackTrace = e.getStackTrace();
if (stackTrace.length > 0) {
sb.append(" stack0: ");
sb.append(stackTrace[0]);
}
Throwable cause = e.getCause();
if (cause != null) {
sb.append(" cause: ");
formatThrowable(cause, sb);
}
}
/**
@@ -381,9 +323,6 @@ public class TransactionManager implements SpiTransactionManager {
@Override
public final void notifyOfCommit(SpiTransaction transaction) {
try {
if (txnLogger.isDebug()) {
txnLogger.debug(transaction.getLogPrefix() + "Commit");
}
PostCommitProcessing postCommit = new PostCommitProcessing(clusterManager, this, transaction);
postCommit.notifyLocalCache();
backgroundExecutor.execute(postCommit.backgroundNotify());
@@ -676,25 +615,18 @@ public class TransactionManager implements SpiTransactionManager {
}
}
/**
* Return true if Transaction debug is on.
*/
public final boolean isTxnDebug() {
return txnDebug;
public SpiTxnLogger logger() {
return logManager.logger();
}
public SpiTxnLogger loggerReadOnly() {
return logManager.readOnlyLogger();
}
public final SpiLogManager log() {
return logManager;
}
public final boolean isLogSql() {
return logManager.sql().isDebug();
}
public final boolean isLogSummary() {
return logManager.sum().isDebug();
}
/**
* Experimental - find dirty beans in the persistence context and persist them.
*/
@@ -704,4 +636,5 @@ public class TransactionManager implements SpiTransactionManager {
server.updateAll(dirtyBeans, transaction);
}
}
}
@@ -43,4 +43,24 @@ public final class Str {
return sb.append(s0).append(s1).toString();
}
public static String add(String s0, String[] s1) {
if (s1 == null || s1.length == 0) {
return s0;
}
int len = s0.length();
for (String s : s1) {
if (s != null) {
len += s.length();
}
}
StringBuilder sb = new StringBuilder(len);
sb.append(s0);
for (String s : s1) {
if (s != null) {
sb.append(s);
}
}
return sb.toString();
}
}
@@ -2,6 +2,7 @@ package io.ebean.test;
import io.ebeaninternal.api.SpiLogger;
import java.text.MessageFormat;
import java.util.ArrayList;
import java.util.List;
@@ -24,24 +25,11 @@ final class CaptureLogger implements SpiLogger {
}
@Override
public boolean isTrace() {
return true;
}
@Override
public void debug(String msg) {
public void debug(String msg, Object... args) {
if (active) {
messages.add(msg);
messages.add(MessageFormat.format(msg, args));
}
wrapped.debug(msg);
}
@Override
public void trace(String msg) {
if (active) {
messages.add(msg);
}
wrapped.trace(msg);
wrapped.debug(msg, args);
}
List<String> start() {
@@ -5,7 +5,6 @@ import io.ebeaninternal.api.SpiLogger;
import io.ebeaninternal.api.SpiLoggerFactory;
import static java.lang.System.Logger.Level.DEBUG;
import static java.lang.System.Logger.Level.TRACE;
/**
* Create a logger that captures the SQL and register it for later access in tests.
@@ -38,18 +37,8 @@ public class CapturingLoggerFactory implements SpiLoggerFactory {
}
@Override
public boolean isTrace() {
return logger.isLoggable(TRACE);
}
@Override
public void debug(String msg) {
logger.log(DEBUG, msg);
}
@Override
public void trace(String msg) {
logger.log(TRACE, msg);
public void debug(String msg, Object... args) {
logger.log(DEBUG, msg, args);
}
}
}
@@ -35,16 +35,7 @@ public class EbeanServerFactory_ServerConfigStart_Test {
}
@Override
public boolean isTrace() {
return false;
}
@Override
public void debug(String msg) {
}
@Override
public void trace(String msg) {
public void debug(String msg, Object... args) {
}
};
@@ -34,7 +34,7 @@ public class TransactionManagerTest extends BaseTestCase {
DataSource dataSource = transactionManager.dataSource();
Connection connection = dataSource.getConnection();
try {
SpiTransaction externalTxn = new ExternalJdbcTransaction("external0", true, connection, null);
SpiTransaction externalTxn = new ExternalJdbcTransaction(true, connection, null);
// push an externally managed transaction onto scope
ScopedTransaction scopedTransaction = transactionManager.externalBeginTransaction(externalTxn, TxScope.required());