Disable Hibernate error logging (#2134)

Hibernate logs certain information at the ERROR level, which for the
purpose of troubleshooting is misleading, since most affected operations
succeed after retry. ERROR-level logging should only be added by Nomulus
code.

This PR does two things:
1. Disable all logging in two Hibernate classes: we cannot disable
   logging at a finer granularity, and we cannot preserve lower-level
   logging while disabling ERROR.
2. Adds a DatabaseException which captures all error details that may
   escape the typical loggers' attention: SQLException instances can be
   chained in a different way from Throwable's `getCause()` method.
This commit is contained in:
Weimin Yu 2023-09-06 13:25:21 -04:00 committed by GitHub
parent 335af52112
commit 9a6a7116da
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 420 additions and 4 deletions

View file

@ -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

View file

@ -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

View file

@ -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

View file

@ -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

View file

@ -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}.
*
* <p>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.
*
* <p>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.
*
* <p>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}.
*
* <p>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<String> 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<String> getSqlExceptionDetails(SQLException sqlException) {
ImmutableList.Builder<String> 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<String> errors = errBuilder.build();
if (errors.isEmpty()) {
return Optional.empty();
}
return Optional.of(Joiner.on("\n").join(errors));
}
}

View file

@ -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();

View file

@ -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();
}
}

View file

@ -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.
*
* <p>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;
}
}
}

View file

@ -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");
}

View file

@ -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();