Skip to content

Commit

Permalink
Enhancement logs for better debugging
Browse files Browse the repository at this point in the history
  • Loading branch information
@milanmajchrak
milanmajchrak committed Dec 20, 2024
1 parent 5891751 commit 59bf3fa
Show file tree
Hide file tree
Showing 3 changed files with 45 additions and 14 deletions.
56 changes: 43 additions & 13 deletions dspace-api/src/main/java/org/dspace/core/Context.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
import java.util.concurrent.atomic.AtomicBoolean;

import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
import org.dspace.authorize.ResourcePolicy;
import org.dspace.content.DSpaceObject;
import org.dspace.eperson.EPerson;
Expand Down Expand Up @@ -140,6 +141,8 @@ public enum Mode {
}

protected Context(EventService eventService, DBConnection dbConnection) {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Creating new context with event service and database connection.");
this.eventService = eventService;
this.dbConnection = dbConnection;
init();
Expand All @@ -151,6 +154,8 @@ protected Context(EventService eventService, DBConnection dbConnection) {
* No user is authenticated.
*/
public Context() {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Creating new context.");
init();
}

Expand All @@ -161,6 +166,8 @@ public Context() {
* @param mode The mode to use when opening the context.
*/
public Context(Mode mode) {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Creating new context with mode: {}", mode);
this.mode = mode;
init();
}
Expand All @@ -170,6 +177,7 @@ public Context(Mode mode) {
*/
protected void init() {
try {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Initializing new context, mode: {}", mode);
updateDatabase();

Expand Down Expand Up @@ -397,6 +405,7 @@ public String getExtraLogInfo() {
* or closing the connection
*/
public void complete() throws SQLException {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Completing context.");
// If Context is no longer open/valid, just note that it has already been closed
if (!isValid()) {
Expand All @@ -406,21 +415,22 @@ public void complete() throws SQLException {

try {
if (!isReadOnly()) {
log.info("complete() method - Going to commit transaction - is not read only.");
commit(); // Commit the transaction
}
} catch (Exception e) {
log.error("Error committing transaction in complete()", e);
log.error("complete() method - Error committing transaction.", e);
throw e; // Rethrow to signal failure to higher-level logic
} finally {
log.info("Going to close a connection.");
log.info("complete() method - Going to close a connection.");
if (dbConnection != null) {
try {
log.info("Closing connection.");
log.info("complete() method - Closing connection.");
dbConnection.closeDBConnection();
log.info("Connection closed.");
log.info("complete() method - Connection closed.");
dbConnection = null;
} catch (SQLException ex) {
log.error("Error closing the database connection after complete()", ex);
log.error("complete() method - Error closing the database connection.", ex);
}
}
}
Expand All @@ -437,29 +447,36 @@ public void complete() throws SQLException {
* @throws SQLException When committing the transaction in the database fails.
*/
public void commit() throws SQLException {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Committing context.");
// If Context is no longer open/valid, just note that it has already been closed
if (!isValid()) {
log.info("commit() was called on a closed Context object. No changes to commit.");
return;
}

if (isReadOnly()) {
log.error("commit() method - You cannot commit a read-only context");
throw new UnsupportedOperationException("You cannot commit a read-only context");
}

try {
// Dispatch events before committing changes to the database,
// as the consumers may change something too
log.info("commit() method - Dispatching events.");
dispatchEvents();
} finally {
if (log.isDebugEnabled()) {
log.debug("Cache size on commit is " + getCacheSize());
log.debug("commit() method - Cache size on commit is " + getCacheSize());
}

if (dbConnection != null) {
log.info("commit() method - Committing transaction.");
// Commit our changes (this closes the transaction but leaves database connection open)
dbConnection.commit();
reloadContextBoundEntities();
} else {
log.info("commit() method - No database connection to commit to.");
}
}
}
Expand Down Expand Up @@ -569,16 +586,21 @@ public Event pollEvent() {
* @throws SQLException When rollbacking the transaction in the database fails.
*/
public void rollback() throws SQLException {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Rolling back context.");
// If Context is no longer open/valid, just note that it has already been closed
if (!isValid()) {
log.info("rollback() was called on a closed Context object. No changes to abort.");
return;
}

try {
log.info("rollback() method - Going to rollback transaction.");
// Rollback ONLY if we have a database transaction, and it is NOT Read Only
if (!isReadOnly() && isTransactionAlive()) {
log.info("rollback() method - Rolling back transaction.");
dbConnection.rollback();
log.info("rollback() method - Transaction successfully rolled back.");
reloadContextBoundEntities();
}
} catch (SQLException e) {
Expand All @@ -600,6 +622,7 @@ public void rollback() throws SQLException {
* is a no-op.
*/
public void abort() {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Aborting context.");
// If Context is no longer open/valid, just note that it has already been closed
if (!isValid()) {
Expand All @@ -611,22 +634,22 @@ public void abort() {
// Rollback ONLY if we have a database transaction, and it is NOT Read Only
if (!isReadOnly() && isTransactionAlive()) {
dbConnection.rollback();
log.info("Transaction successfully rolled back during abort().");
log.info("abort() method - Transaction successfully rolled back.");
}
} catch (SQLException se) {
log.error("Error rolling back transaction during an abort()", se);
log.error("abort() method - Error rolling back transaction.", se);
} finally {
try {
log.info("Going to close a connection.");
log.info("abort() method - Going to close a connection.");
if (dbConnection != null) {
log.info("Closing connection.");
log.info("abort() method - Closing connection.");
// Free the DB connection & invalidate the Context
dbConnection.closeDBConnection();
log.info("Database connection closed during abort().");
log.info("abort() method - Database connection closed");
dbConnection = null;
}
} catch (Exception ex) {
log.error("Error closing the database connection during abort()", ex);
log.error("abort() method - Error closing the database connection.", ex);
}
events = null; // Clear events to release resources
}
Expand All @@ -638,12 +661,15 @@ public void abort() {
*/
@Override
public void close() {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Closing context.");
try {
if (isValid()) {
log.info("close() method - calling abort().");
abort();
}
} catch (Exception e) {
log.error("Error during context closure", e);
log.error("close() method - Error during context closure", e);
}
}

Expand Down Expand Up @@ -768,14 +794,18 @@ public void restoreContextUser() {
*/
@Override
protected void finalize() throws Throwable {
ThreadContext.put("classID", String.valueOf(System.identityHashCode(this)));
log.info("Finalizing context.");
/*
* If a context is garbage-collected, we roll back and free up the
* database connection if there is one.
*/
if (dbConnection != null && dbConnection.isTransActionAlive()) {
log.info("finalize() method - calling abort()");
abort();
}

log.info("finalize() method - calling super.finalize().");
super.finalize();
}

Expand Down
2 changes: 1 addition & 1 deletion dspace/config/log4j2.xml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@
<!-- NOTE: The %equals patterns are providing a default value of "unknown" if "correlationID" or
"requestID" are not currently set in the ThreadContext. -->
<Layout type='PatternLayout'
pattern='%d %t %-5p %equals{%X{correlationID}}{}{unknown} %equals{%X{requestID}}{}{unknown} %c @ %m%n'/>
pattern='%d %equals{%X{classID}}{}{unknown} %t %-5p %equals{%X{correlationID}}{}{unknown} %equals{%X{requestID}}{}{unknown} %c @ %m%n'/>
<policies>
<policy type='TimeBasedTriggeringPolicy'>yyyy-MM-dd</policy>
</policies>
Expand Down
1 change: 1 addition & 0 deletions dspace/config/spring/api/core-hibernate.xml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -52,6 +52,7 @@
<property name="maxConnLifetimeMillis" value="${db.maxconnlifetime}"/>
<property name="removeAbandonedOnBorrow" value="${db.removeabandoned}"/>
<property name="removeAbandonedTimeout" value="${db.removeabandonedtimeout}"/>
<property name="logAbandoned" value="true"/>
</bean>

</beans>

0 comments on commit 59bf3fa

Please sign in to comment.