diff --git a/core/src/main/java/google/registry/env/common/backend/WEB-INF/logging.properties b/core/src/main/java/google/registry/env/common/backend/WEB-INF/logging.properties index 064aa4905..487bddee4 100644 --- a/core/src/main/java/google/registry/env/common/backend/WEB-INF/logging.properties +++ b/core/src/main/java/google/registry/env/common/backend/WEB-INF/logging.properties @@ -11,3 +11,7 @@ # Set the default logging level for all loggers to INFO. .level = INFO + +# Turn off logging in Hibernate classes for misleading ERROR-level logs +org.hibernate.engine.jdbc.batch.internal.BatchingBatch.level=OFF +org.hibernate.engine.jdbc.spi.SqlExceptionHelper.level=OFF diff --git a/core/src/main/java/google/registry/env/common/default/WEB-INF/logging.properties b/core/src/main/java/google/registry/env/common/default/WEB-INF/logging.properties index 064aa4905..487bddee4 100644 --- a/core/src/main/java/google/registry/env/common/default/WEB-INF/logging.properties +++ b/core/src/main/java/google/registry/env/common/default/WEB-INF/logging.properties @@ -11,3 +11,7 @@ # Set the default logging level for all loggers to INFO. .level = INFO + +# Turn off logging in Hibernate classes for misleading ERROR-level logs +org.hibernate.engine.jdbc.batch.internal.BatchingBatch.level=OFF +org.hibernate.engine.jdbc.spi.SqlExceptionHelper.level=OFF diff --git a/core/src/main/java/google/registry/env/common/pubapi/WEB-INF/logging.properties b/core/src/main/java/google/registry/env/common/pubapi/WEB-INF/logging.properties index 064aa4905..487bddee4 100644 --- a/core/src/main/java/google/registry/env/common/pubapi/WEB-INF/logging.properties +++ b/core/src/main/java/google/registry/env/common/pubapi/WEB-INF/logging.properties @@ -11,3 +11,7 @@ # Set the default logging level for all loggers to INFO. .level = INFO + +# Turn off logging in Hibernate classes for misleading ERROR-level logs +org.hibernate.engine.jdbc.batch.internal.BatchingBatch.level=OFF +org.hibernate.engine.jdbc.spi.SqlExceptionHelper.level=OFF diff --git a/core/src/main/java/google/registry/env/common/tools/WEB-INF/logging.properties b/core/src/main/java/google/registry/env/common/tools/WEB-INF/logging.properties index 064aa4905..487bddee4 100644 --- a/core/src/main/java/google/registry/env/common/tools/WEB-INF/logging.properties +++ b/core/src/main/java/google/registry/env/common/tools/WEB-INF/logging.properties @@ -11,3 +11,7 @@ # Set the default logging level for all loggers to INFO. .level = INFO + +# Turn off logging in Hibernate classes for misleading ERROR-level logs +org.hibernate.engine.jdbc.batch.internal.BatchingBatch.level=OFF +org.hibernate.engine.jdbc.spi.SqlExceptionHelper.level=OFF diff --git a/core/src/main/java/google/registry/persistence/transaction/DatabaseException.java b/core/src/main/java/google/registry/persistence/transaction/DatabaseException.java new file mode 100644 index 000000000..90f9e7564 --- /dev/null +++ b/core/src/main/java/google/registry/persistence/transaction/DatabaseException.java @@ -0,0 +1,112 @@ +// Copyright 2023 The Nomulus Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package google.registry.persistence.transaction; + +import autovalue.shaded.com.google.common.collect.ImmutableList; +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.Joiner; +import java.sql.SQLException; +import java.util.Optional; +import javax.persistence.PersistenceException; + +/** + * Wraps an exception thrown by the JPA framework and captures the SQL error details (state and + * status code) in the {@link #getMessage message}. + * + *

The {@link SQLException} class has its own chain of exceptions that describe multiple error + * conditions encontered during a transaction. A typical logger relying on the {@link + * Throwable#getCause() chain of causes} in {@code Throwable} instances cannot capture all details + * of errors thrown from the database drivers. This exception captures all error details in its + * message text. + * + *

The {@link TransactionManager} wraps every persistence exception in an instance of this class. + * This allows us to disable logging in specific Hibernate classes that logs at {@code ERROR}-level + * and rethrows. These {@code ERROR} logs are misleading, since the impacted transactions often + * succeeds on retries. + * + *

See the {@code logging.properties} files in the {@code env} package for the specific Hibernate + * classes that have logging suppressed. + */ +class DatabaseException extends PersistenceException { + + private transient String cachedMessage; + + @VisibleForTesting + DatabaseException(Throwable throwable) { + super(throwable); + } + + @Override + public String getMessage() { + if (cachedMessage == null) { + cachedMessage = getSqlError(getCause()); + } + return cachedMessage; + } + + /** + * Throws an unchecked exception on behalf of the {@code original} {@link Throwable}. + * + *

If the {@code original Throwable} has at least one {@link SQLException} in its chain of + * causes, a {@link DatabaseException} is thrown; otherwise this does nothing. + */ + static void tryWrapAndThrow(Throwable original) { + Throwable t = original; + do { + if (t instanceof SQLException) { + throw new DatabaseException(original); + } + } while ((t = t.getCause()) != null); + } + + /** + * Returns the SQL state and error code of every {@link SQLException} in the chain of causes, or + * empty string if such information is not found. + */ + static String getSqlError(Throwable t) { + ImmutableList.Builder errMessageBuilder = new ImmutableList.Builder<>(); + do { + if (t instanceof SQLException) { + SQLException e = (SQLException) t; + getSqlExceptionDetails(e).ifPresent(errMessageBuilder::add); + } + t = t.getCause(); + } while (t != null); + return Joiner.on("\n").join(errMessageBuilder.build()); + } + + static Optional getSqlExceptionDetails(SQLException sqlException) { + ImmutableList.Builder errBuilder = new ImmutableList.Builder<>(); + + while (sqlException != null) { + if (sqlException.getErrorCode() > 0 || sqlException.getSQLState() != null) { + errBuilder.add( + "\tSQL Error: " + + sqlException.getErrorCode() + + ", SQLState: " + + sqlException.getSQLState() + + ", message: " + + sqlException.getMessage() + + "."); + } + sqlException = sqlException.getNextException(); + } + ImmutableList errors = errBuilder.build(); + if (errors.isEmpty()) { + return Optional.empty(); + } + return Optional.of(Joiner.on("\n").join(errors)); + } +} diff --git a/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java b/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java index 491a537d2..ecb725f15 100644 --- a/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java +++ b/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java @@ -19,6 +19,7 @@ import static com.google.common.collect.ImmutableList.toImmutableList; import static com.google.common.collect.ImmutableMap.toImmutableMap; import static com.google.common.collect.ImmutableSet.toImmutableSet; import static google.registry.config.RegistryConfig.getHibernatePerTransactionIsolationEnabled; +import static google.registry.persistence.transaction.DatabaseException.tryWrapAndThrow; import static google.registry.util.PreconditionsUtils.checkArgumentNotNull; import static java.util.AbstractMap.SimpleEntry; import static java.util.stream.Collectors.joining; @@ -213,6 +214,7 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager { } catch (Throwable rollbackException) { logger.atSevere().withCause(rollbackException).log("Rollback failed; suppressing error."); } + tryWrapAndThrow(e); throw e; } finally { txnInfo.clear(); diff --git a/core/src/test/java/google/registry/persistence/transaction/DatabaseExceptionTest.java b/core/src/test/java/google/registry/persistence/transaction/DatabaseExceptionTest.java new file mode 100644 index 000000000..b958a4fa0 --- /dev/null +++ b/core/src/test/java/google/registry/persistence/transaction/DatabaseExceptionTest.java @@ -0,0 +1,119 @@ +// Copyright 2023 The Nomulus Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package google.registry.persistence.transaction; + +import static com.google.common.truth.Truth.assertThat; +import static com.google.common.truth.Truth8.assertThat; +import static google.registry.persistence.transaction.DatabaseException.getSqlError; +import static google.registry.persistence.transaction.DatabaseException.getSqlExceptionDetails; +import static google.registry.persistence.transaction.DatabaseException.tryWrapAndThrow; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; + +import java.sql.SQLException; +import org.junit.jupiter.api.Test; + +/** Unit tests for {@link DatabaseException}. */ +public class DatabaseExceptionTest { + + @Test + void getSqlError_singleNonSqlException() { + assertThat(getSqlError(new Exception())).isEmpty(); + } + + @Test + void getSqlExceptionDetails_chainedNoSqlExceptions() { + assertThat(getSqlError(new Exception(new Exception()))).isEmpty(); + } + + @Test + void getSqlError_sqlExceptionNoDetails() { + assertThat(getSqlError(new java.sql.SQLException())).isEmpty(); + } + + @Test + void getSqlError_sqlExceptionWithSqlState() { + assertThat(getSqlError(new java.sql.SQLException("msg", "state"))) + .contains("\tSQL Error: 0, SQLState: state, message: msg."); + } + + @Test + void getSqlError_sqlExceptionWithAllDetails() { + assertThat(getSqlError(new java.sql.SQLException("msg", "state", 1))) + .contains("\tSQL Error: 1, SQLState: state, message: msg."); + } + + @Test + void getSqlError_chainedSqlExceptionWithAllDetails() { + SQLException sqlException = new java.sql.SQLException("msg", "state", 1); + assertThat(getSqlError(new Exception("not-captured", sqlException))) + .contains("\tSQL Error: 1, SQLState: state, message: msg."); + } + + @Test + void getSqlError_multipleChainedSqlExceptionWithAllDetails() { + SQLException lower = new java.sql.SQLException("lower", "lower-state", 1); + SQLException higher = + new java.sql.SQLException("higher", "higher-state", 2, new Exception(lower)); + assertThat(getSqlError(new Exception(higher))) + .contains( + "\tSQL Error: 2, SQLState: higher-state, message: higher.\n" + + "\tSQL Error: 1, SQLState: lower-state, message: lower."); + } + + @Test + void getSqlExceptionDetails_singleNoDetails() { + assertThat(getSqlExceptionDetails(new SQLException())).isEmpty(); + } + + @Test + void getSqlExceptionDetails_singleWithDetails() { + assertThat(getSqlExceptionDetails(new SQLException("msg", "state", 1))) + .hasValue("\tSQL Error: 1, SQLState: state, message: msg."); + } + + @Test + void getSqlExceptionDetails_multipleWithDetails() { + SQLException first = new SQLException("msg", "state", 1); + first.setNextException(new SQLException("msg2", "state2", 2)); + assertThat(getSqlExceptionDetails(first)) + .hasValue( + "\tSQL Error: 1, SQLState: state, message: msg.\n" + + "\tSQL Error: 2, SQLState: state2, message: msg2."); + } + + @Test + void tryWrapAndThrow_notSQLException() { + RuntimeException orig = new RuntimeException(new Exception()); + tryWrapAndThrow(orig); + } + + @Test + void tryWrapAndThrow_hasSQLException() { + Throwable orig = new Throwable(new SQLException()); + assertThrows(DatabaseException.class, () -> tryWrapAndThrow(orig)); + } + + @Test + void getMessage_cachedMessageReused() { + SQLException sqlException = mock(SQLException.class); + DatabaseException databaseException = new DatabaseException(sqlException); + databaseException.getMessage(); + databaseException.getMessage(); + verify(sqlException, times(1)).getCause(); + } +} diff --git a/core/src/test/java/google/registry/persistence/transaction/HibernateLoggingSuppressionTest.java b/core/src/test/java/google/registry/persistence/transaction/HibernateLoggingSuppressionTest.java new file mode 100644 index 000000000..92ba4ae85 --- /dev/null +++ b/core/src/test/java/google/registry/persistence/transaction/HibernateLoggingSuppressionTest.java @@ -0,0 +1,160 @@ +// Copyright 2023 The Nomulus Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package google.registry.persistence.transaction; + +import static com.google.common.base.Preconditions.checkArgument; +import static com.google.common.truth.Truth.assertThat; +import static google.registry.persistence.transaction.TransactionManagerFactory.tm; +import static java.nio.charset.StandardCharsets.UTF_8; +import static java.util.logging.Logger.getLogger; + +import com.google.common.testing.TestLogHandler; +import google.registry.persistence.transaction.JpaTestExtensions.JpaUnitTestExtension; +import java.io.ByteArrayInputStream; +import java.io.IOException; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.Logger; +import javax.persistence.Entity; +import javax.persistence.Id; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; + +/** + * Verifies that specific {@code ERROR}-level logging by Hibernate does not appear in the log files. + * + *

Please refer to the class javadoc of {@link DatabaseException} for more information. + */ +public class HibernateLoggingSuppressionTest { + + private static final String LOG_SUPPRESSION_TARGET = + "org.hibernate.engine.jdbc.spi.SqlExceptionHelper"; + + // The line that should be added to the `logging.properties` file. + private static final String LOGGING_PROPERTIES_LINE = LOG_SUPPRESSION_TARGET + ".level=OFF\n"; + + @RegisterExtension + public final JpaUnitTestExtension jpa = + new JpaTestExtensions.Builder() + .withoutCannedData() + .withEntityClass(TestEntity.class) + .buildUnitTestExtension(); + + private Logger logger; + private TestLogHandler testLogHandler; + + @BeforeEach + void setup() { + testLogHandler = new TestLogHandler(); + logger = getLogger(LOG_SUPPRESSION_TARGET); + logger.addHandler(testLogHandler); + } + + @AfterEach + void teardown() { + logger.removeHandler(testLogHandler); + } + + // Updates logging configs to suppress logging. Call `revertSuppressionOfHibernateLogs` to revert. + void suppressHibernateLogs() throws IOException { + try (ByteArrayInputStream additionalProperties = + new ByteArrayInputStream(LOGGING_PROPERTIES_LINE.getBytes(UTF_8))) { + LogManager.getLogManager() + .updateConfiguration( + additionalProperties, + x -> + (o, n) -> { + if (!x.startsWith(LOG_SUPPRESSION_TARGET)) { + return o; + } + checkArgument(o == null, "Cannot override old value in this test"); + return n; + }); + } + } + + void revertSuppressionOfHibernateLogs() throws IOException { + try (ByteArrayInputStream additionalProperties = + new ByteArrayInputStream(LOGGING_PROPERTIES_LINE.getBytes(UTF_8))) { + LogManager.getLogManager() + .updateConfiguration( + additionalProperties, + x -> + (o, n) -> { + if (!x.startsWith(LOG_SUPPRESSION_TARGET)) { + return o; + } + return null; + }); + } + } + + @Test + void noLoggingSuppression() { + try { + tm().transact(() -> tm().insert(new TestEntity(1, 1))); + tm().transact(() -> tm().insert(new TestEntity(1, 1))); + } catch (DatabaseException e) { + assertThat(e).hasMessageThat().contains("SQLState: "); + } + assertThat( + testLogHandler.getStoredLogRecords().stream() + .anyMatch( + logRecord -> + logRecord.getLevel().equals(Level.SEVERE) + && logRecord.getMessage().contains("duplicate key"))) + .isTrue(); + } + + @Test + void withLoggingSuppression() throws Exception { + suppressHibernateLogs(); + try { + tm().transact(() -> tm().insert(new TestEntity(1, 1))); + tm().transact(() -> tm().insert(new TestEntity(1, 1))); + } catch (DatabaseException e) { + assertThat(e).hasMessageThat().contains("SQLState: "); + } + assertThat( + testLogHandler.getStoredLogRecords().stream() + .anyMatch( + logRecord -> + logRecord.getLevel().equals(Level.SEVERE) + && logRecord.getMessage().contains("duplicate key"))) + .isFalse(); + revertSuppressionOfHibernateLogs(); + } + + @Entity + static class TestEntity { + @Id long id; + int value; + + // For Hibernate + TestEntity() {} + + TestEntity(long id, int value) { + this.id = id; + this.value = value; + } + + TestEntity incValue() { + this.value++; + return this; + } + } +} diff --git a/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerExtensionTest.java b/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerExtensionTest.java index c679276c2..1d47321f8 100644 --- a/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerExtensionTest.java +++ b/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerExtensionTest.java @@ -64,8 +64,9 @@ public class JpaTransactionManagerExtensionTest { TestEntity testEntity = new TestEntity("foo", "bar"); assertThat( assertThrows( - PersistenceException.class, - () -> replicaTm().transact(() -> replicaTm().put(testEntity)))) + PersistenceException.class, + () -> replicaTm().transact(() -> replicaTm().put(testEntity))) + .getCause()) .hasMessageThat() .isEqualTo("Error while committing the transaction"); } diff --git a/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerImplTest.java b/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerImplTest.java index 8d6346a64..454529965 100644 --- a/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerImplTest.java +++ b/core/src/test/java/google/registry/persistence/transaction/JpaTransactionManagerImplTest.java @@ -49,6 +49,7 @@ import javax.persistence.EntityManager; import javax.persistence.Id; import javax.persistence.IdClass; import javax.persistence.OptimisticLockException; +import javax.persistence.PersistenceException; import javax.persistence.RollbackException; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; @@ -353,7 +354,11 @@ class JpaTransactionManagerImplTest { tm().transact(() -> tm().insert(theEntity)); assertThat(existsInDb(theEntity)).isTrue(); assertThat(loadByKey(theEntityKey)).isEqualTo(theEntity); - assertThrows(RollbackException.class, () -> tm().transact(() -> tm().insert(theEntity))); + assertThat( + assertThrows( + PersistenceException.class, () -> tm().transact(() -> tm().insert(theEntity))) + .getCause()) + .isInstanceOf(RollbackException.class); } @Test @@ -389,7 +394,8 @@ class JpaTransactionManagerImplTest { void saveAllNew_rollsBackWhenFailure() { moreEntities.forEach(entity -> assertThat(tm().transact(() -> tm().exists(entity))).isFalse()); insertInDb(moreEntities.get(0)); - assertThrows(RollbackException.class, () -> insertInDb(moreEntities)); + assertThat(assertThrows(PersistenceException.class, () -> insertInDb(moreEntities)).getCause()) + .isInstanceOf(RollbackException.class); assertThat(tm().transact(() -> tm().exists(moreEntities.get(0)))).isTrue(); assertThat(tm().transact(() -> tm().exists(moreEntities.get(1)))).isFalse(); assertThat(tm().transact(() -> tm().exists(moreEntities.get(2)))).isFalse();