More HSQLDB deadlock debugging

log4j2.properties

@@ -11,8 +11,8 @@ logger.hsqldb.name = hsqldb.db
 logger.hsqldb.level = warn
 
 # Support optional, per-session HSQLDB debugging
-logger.hsqldbDebug.name = org.qora.repository.hsqldb.HSQLDBRepository
-logger.hsqldbDebug.level = debug
+logger.hsqldbRepository.name = org.qora.repository.hsqldb
+logger.hsqldbRepository.level = trace
 
 # Suppress extraneous Jersey warning
 logger.jerseyInject.name = org.glassfish.jersey.internal.inject.Providers

src/main/java/org/qora/repository/AccountRepository.java

@@ -23,6 +23,9 @@ public interface AccountRepository {
 	/** Returns account's flags or null if account not found. */
 	public Integer getFlags(String address) throws DataException;
 
+	/** Returns whether account exists. */
+	public boolean accountExists(String address) throws DataException;
+
 	/** Returns number of accounts enabled to forge by given address. */
 	public int countForgingAccountsEnabledByAddress(String address) throws DataException;
 

src/main/java/org/qora/repository/Repository.java

@@ -33,6 +33,8 @@ public interface Repository extends AutoCloseable {
 
 	public void rebuild() throws DataException;
 
+	public boolean getDebug();
+
 	public void setDebug(boolean debugState);
 
 }

src/main/java/org/qora/repository/hsqldb/HSQLDBAccountRepository.java

@@ -85,6 +85,15 @@ public class HSQLDBAccountRepository implements AccountRepository {
 		}
 	}
 
+	@Override
+	public boolean accountExists(String address) throws DataException {
+		try {
+			return this.repository.exists("Accounts", "account = ?", address);
+		} catch (SQLException e) {
+			throw new DataException("Unable to check for account in repository", e);
+		}
+	}
+
 	@Override
 	public int countForgingAccountsEnabledByAddress(String address) throws DataException {
 		try (ResultSet resultSet = this.repository.checkedExecute("SELECT COUNT(*) FROM Accounts WHERE forging_enabler = ? LIMIT 1", address)) {
@@ -96,16 +105,33 @@ public class HSQLDBAccountRepository implements AccountRepository {
 
 	@Override
 	public void ensureAccount(AccountData accountData) throws DataException {
-		HSQLDBSaver saveHelper = new HSQLDBSaver("Accounts");
+		byte[] publicKey = accountData.getPublicKey();
 
-		saveHelper.bind("account", accountData.getAddress());
+		try (ResultSet resultSet = this.repository.checkedExecute("SELECT public_key FROM Accounts WHERE account = ?", accountData.getAddress())) {
+			if (resultSet != null) {
+				// We know account record exists at this point.
+				// If accountData has no public key then we're done.
+				// If accountData's public key matches repository's public key then we're done.
+				if (publicKey == null || Arrays.equals(resultSet.getBytes(1), publicKey))
+					return;
+			}
 
-		byte[] publicKey = accountData.getPublicKey();
-		if (publicKey != null)
-			saveHelper.bind("public_key", publicKey);
+			// No record exists, or we have a public key to set
+			HSQLDBSaver saveHelper = new HSQLDBSaver("Accounts");
+
+			saveHelper.bind("account", accountData.getAddress());
+
+			if (publicKey != null)
+				saveHelper.bind("public_key", publicKey);
+
+			// XXX TMP DEBUGGING
+			boolean priorDebug = this.repository.getDebug();
+			this.repository.setDebug(true);
 
-		try {
 			saveHelper.execute(this.repository);
+
+			// XXX TMP DEBUGGING
+			this.repository.setDebug(priorDebug);
 		} catch (SQLException e) {
 			throw new DataException("Unable to ensure minimal account in repository", e);
 		}
@@ -122,7 +148,14 @@ public class HSQLDBAccountRepository implements AccountRepository {
 			saveHelper.bind("public_key", publicKey);
 
 		try {
+			// XXX TMP DEBUGGING
+			boolean priorDebug = this.repository.getDebug();
+			this.repository.setDebug(true);
+
 			saveHelper.execute(this.repository);
+
+			// XXX TMP DEBUGGING
+			this.repository.setDebug(priorDebug);
 		} catch (SQLException e) {
 			throw new DataException("Unable to save account's last reference into repository", e);
 		}
@@ -139,7 +172,14 @@ public class HSQLDBAccountRepository implements AccountRepository {
 			saveHelper.bind("public_key", publicKey);
 
 		try {
+			// XXX TMP DEBUGGING
+			boolean priorDebug = this.repository.getDebug();
+			this.repository.setDebug(true);
+
 			saveHelper.execute(this.repository);
+
+			// XXX TMP DEBUGGING
+			this.repository.setDebug(priorDebug);
 		} catch (SQLException e) {
 			throw new DataException("Unable to save account's default group ID into repository", e);
 		}
@@ -156,7 +196,14 @@ public class HSQLDBAccountRepository implements AccountRepository {
 			saveHelper.bind("public_key", publicKey);
 
 		try {
+			// XXX TMP DEBUGGING
+			boolean priorDebug = this.repository.getDebug();
+			this.repository.setDebug(true);
+
 			saveHelper.execute(this.repository);
+
+			// XXX TMP DEBUGGING
+			this.repository.setDebug(priorDebug);
 		} catch (SQLException e) {
 			throw new DataException("Unable to save account's flags into repository", e);
 		}
@@ -173,7 +220,14 @@ public class HSQLDBAccountRepository implements AccountRepository {
 			saveHelper.bind("public_key", publicKey);
 
 		try {
+			// XXX TMP DEBUGGING
+			boolean priorDebug = this.repository.getDebug();
+			this.repository.setDebug(true);
+
 			saveHelper.execute(this.repository);
+
+			// XXX TMP DEBUGGING
+			this.repository.setDebug(priorDebug);
 		} catch (SQLException e) {
 			throw new DataException("Unable to save account's forging enabler into repository", e);
 		}

src/main/java/org/qora/repository/hsqldb/HSQLDBRepository.java

@@ -44,15 +44,33 @@ public class HSQLDBRepository implements Repository {
 	protected boolean debugState = false;
 	protected Long slowQueryThreshold = null;
 	protected List<String> sqlStatements;
+	protected long sessionId;
 
 	// NB: no visibility modifier so only callable from within same package
-	HSQLDBRepository(Connection connection) {
+	HSQLDBRepository(Connection connection) throws DataException {
 		this.connection = connection;
 		this.savepoints = new ArrayDeque<>(3);
 
 		this.slowQueryThreshold = Settings.getInstance().getSlowQueryThreshold();
 		if (this.slowQueryThreshold != null)
 			this.sqlStatements = new ArrayList<String>();
+
+		// Find out our session ID
+		try (Statement stmt = this.connection.createStatement()) {
+			if (!stmt.execute("SELECT SESSION_ID()"))
+				throw new DataException("Unable to fetch session ID from repository");
+
+			try (ResultSet resultSet = stmt.getResultSet()) {
+				if (resultSet == null || !resultSet.next())
+					LOGGER.warn("Unable to fetch session ID from repository");
+
+				this.sessionId = resultSet.getLong(1);
+			}
+		} catch (SQLException e) {
+			throw new DataException("Unable to fetch session ID from repository", e);
+		}
+
+		assertEmptyTransaction("connection creation");
 	}
 
 	@Override
@@ -109,6 +127,9 @@ public class HSQLDBRepository implements Repository {
 		} finally {
 			this.savepoints.clear();
 
+			// Before clearing statements so we can log what led to assertion error
+			assertEmptyTransaction("transaction commit");
+
 			if (this.sqlStatements != null)
 				this.sqlStatements.clear();
 		}
@@ -123,6 +144,9 @@ public class HSQLDBRepository implements Repository {
 		} finally {
 			this.savepoints.clear();
 
+			// Before clearing statements so we can log what led to assertion error
+			assertEmptyTransaction("transaction commit");
+
 			if (this.sqlStatements != null)
 				this.sqlStatements.clear();
 		}
@@ -172,21 +196,7 @@ public class HSQLDBRepository implements Repository {
 		}
 
 		try (Statement stmt = this.connection.createStatement()) {
-			// Diagnostic check for uncommitted changes
-			if (!stmt.execute("SELECT transaction, transaction_size FROM information_schema.system_sessions")) // TRANSACTION_SIZE() broken?
-				throw new DataException("Unable to check repository status during close");
-
-			try (ResultSet resultSet = stmt.getResultSet()) {
-				if (resultSet == null || !resultSet.next())
-					LOGGER.warn("Unable to check repository status during close");
-
-				boolean inTransaction = resultSet.getBoolean(1);
-				int transactionCount = resultSet.getInt(2);
-				if (inTransaction && transactionCount != 0) {
-					LOGGER.warn("Uncommitted changes (" + transactionCount + ") during repository close", new Exception("Uncommitted repository changes"));
-					logStatements();
-				}
-			}
+			assertEmptyTransaction("connection close");
 
 			// give connection back to the pool
 			this.connection.close();
@@ -200,6 +210,11 @@ public class HSQLDBRepository implements Repository {
 	public void rebuild() throws DataException {
 	}
 
+	@Override
+	public boolean getDebug() {
+		return this.debugState;
+	}
+
 	@Override
 	public void setDebug(boolean debugState) {
 		this.debugState = debugState;
@@ -210,7 +225,7 @@ public class HSQLDBRepository implements Repository {
 	 */
 	public PreparedStatement prepareStatement(String sql) throws SQLException {
 		if (this.debugState)
-			LOGGER.debug(sql);
+			LOGGER.debug(String.format("[%d] %s", this.sessionId, sql));
 
 		if (this.sqlStatements != null)
 			this.sqlStatements.add(sql);
@@ -227,6 +242,8 @@ public class HSQLDBRepository implements Repository {
 		if (this.sqlStatements == null)
 			return;
 
+		LOGGER.info("HSQLDB SQL statements leading up to this were:");
+
 		for (String sql : this.sqlStatements)
 			LOGGER.info(sql);
 	}
@@ -461,6 +478,29 @@ public class HSQLDBRepository implements Repository {
 		return e;
 	}
 
+	private void assertEmptyTransaction(String context) throws DataException {
+		try (Statement stmt = this.connection.createStatement()) {
+			// Diagnostic check for uncommitted changes
+			if (!stmt.execute("SELECT transaction, transaction_size FROM information_schema.system_sessions WHERE session_id = " + this.sessionId)) // TRANSACTION_SIZE() broken?
+				throw new DataException("Unable to check repository status after " + context);
+
+			try (ResultSet resultSet = stmt.getResultSet()) {
+				if (resultSet == null || !resultSet.next())
+					LOGGER.warn("Unable to check repository status after " + context);
+
+				boolean inTransaction = resultSet.getBoolean(1);
+				int transactionCount = resultSet.getInt(2);
+
+				if (inTransaction && transactionCount != 0) {
+					LOGGER.warn(String.format("Uncommitted changes (%d) after %s, session [%d]", transactionCount, context, this.sessionId), new Exception("Uncommitted repository changes"));
+					logStatements();
+				}
+			}
+		} catch (SQLException e) {
+			throw new DataException("Error checking repository status after " + context, e);
+		}
+	}
+
 	/** Converts milliseconds from epoch to OffsetDateTime needed for TIMESTAMP WITH TIME ZONE columns. */
 	/* package */ static OffsetDateTime toOffsetDateTime(long timestamp) {
 		return OffsetDateTime.ofInstant(Instant.ofEpochMilli(timestamp), ZoneOffset.UTC);