Skip to content

Commit c2e932b

Browse files
snazyadutra
snazy
and
adutra
authored
Fix arg-matching in ExceptionMapperTest.testFullExceptionIsLogged() (#2531)
The above test asserts the the log record passed to `org.jboss.logmanager.Logger#logRaw(org.jboss.logmanager.ExtLogRecord)`. For the sake of this test, both the `IcebergJsonProcessingExceptionMapper` and `IcebergExceptionMapper` have a visible-for-testing function `getLogger()` to provide a mocked logger. `getLogger()` however is used for "all the logging", which makes the behavior `verify(JBOSS_LOGGER).logRaw(argThat(...))` "interesting" - the test fails with #2461 although no related dependencies have changed in that PR. But eventually the test failure's caused by using `getLogger()` for all logging, which may provide the _wrong_ log record and cause the test to fail. This change renames the `getLogger()` functions to make their special meaning clear, and adds some clarifying comments in the code. Also adding some more test cases for the various exception mapper code paths. Co-authored-by: Alexandre Dutra <[email protected]>
1 parent 9b3d7d2 commit c2e932b

File tree

3 files changed

+76
-29
lines changed

3 files changed

+76
-29
lines changed

‎runtime/service/src/main/java/org/apache/polaris/service/exception/IcebergExceptionMapper.java

Lines changed: 14 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -89,15 +89,16 @@ public class IcebergExceptionMapper implements ExceptionMapper<RuntimeException>
8989

9090
@Override
9191
public Response toResponse(RuntimeException runtimeException) {
92-
getLogger().info("Handling runtimeException {}", runtimeException.getMessage());
92+
LOGGER.info("Handling runtimeException {}", runtimeException.getMessage());
9393

9494
int responseCode = mapExceptionToResponseCode(runtimeException);
95-
getLogger()
96-
.atLevel(responseCode >= 500 ? Level.INFO : Level.DEBUG)
97-
.log("Full RuntimeException", runtimeException);
98-
99-
if (responseCode == Response.Status.INTERNAL_SERVER_ERROR.getStatusCode()) {
100-
getLogger().error("Unhandled exception returning INTERNAL_SERVER_ERROR", runtimeException);
95+
if (responseCode == Status.INTERNAL_SERVER_ERROR.getStatusCode()) {
96+
getLoggerForExceptionLogging()
97+
.error("Unhandled exception returning INTERNAL_SERVER_ERROR", runtimeException);
98+
} else {
99+
getLoggerForExceptionLogging()
100+
.atLevel(responseCode > 500 ? Level.INFO : Level.DEBUG)
101+
.log("Full RuntimeException", runtimeException);
101102
}
102103

103104
ErrorResponse icebergErrorResponse =
@@ -111,7 +112,7 @@ public Response toResponse(RuntimeException runtimeException) {
111112
.entity(icebergErrorResponse)
112113
.type(MediaType.APPLICATION_JSON_TYPE)
113114
.build();
114-
getLogger().debug("Mapped exception to errorResp: {}", errorResp);
115+
LOGGER.debug("Mapped exception to errorResp: {}", errorResp);
115116
return errorResp;
116117
}
117118

@@ -261,8 +262,12 @@ static Optional<Integer> mapCloudExceptionToResponseCode(Throwable t) {
261262
return Optional.of(Status.INTERNAL_SERVER_ERROR.getStatusCode());
262263
}
263264

265+
/**
266+
* This function is only present for the {@code ExceptionMapperTest} and must only be used once
267+
* during any execution of {@link #toResponse(RuntimeException)}.
268+
*/
264269
@VisibleForTesting
265-
Logger getLogger() {
270+
Logger getLoggerForExceptionLogging() {
266271
return LOGGER;
267272
}
268273
}

‎runtime/service/src/main/java/org/apache/polaris/service/exception/IcebergJsonProcessingExceptionMapper.java

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,7 @@ public Response toResponse(JsonProcessingException exception) {
6161
if (exception instanceof JsonGenerationException
6262
|| exception instanceof InvalidDefinitionException) {
6363
long id = ThreadLocalRandom.current().nextLong();
64-
getLogger()
64+
getLoggerForExceptionLogging()
6565
.error(String.format(Locale.ROOT, "Error handling a request: %016x", id), exception);
6666
String message =
6767
String.format(
@@ -77,8 +77,8 @@ public Response toResponse(JsonProcessingException exception) {
7777
/*
7878
* Otherwise, it's those pesky users.
7979
*/
80-
getLogger().info("Unable to process JSON: {}", exception.getMessage());
81-
getLogger().debug("Full JsonProcessingException", exception);
80+
LOGGER.info("Unable to process JSON: {}", exception.getMessage());
81+
getLoggerForExceptionLogging().debug("Full JsonProcessingException", exception);
8282

8383
String messagePrefix =
8484
switch (exception) {
@@ -99,8 +99,12 @@ public Response toResponse(JsonProcessingException exception) {
9999
.build();
100100
}
101101

102+
/**
103+
* This function is only present for the {@code ExceptionMapperTest} and must only be used during
104+
* once any execution of {@link #toResponse(JsonProcessingException)}.
105+
*/
102106
@VisibleForTesting
103-
Logger getLogger() {
107+
Logger getLoggerForExceptionLogging() {
104108
return LOGGER;
105109
}
106110
}

‎runtime/service/src/test/java/org/apache/polaris/service/exception/ExceptionMapperTest.java

Lines changed: 54 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -18,21 +18,25 @@
1818
*/
1919
package org.apache.polaris.service.exception;
2020

21+
import static org.assertj.core.api.Assertions.assertThat;
2122
import static org.mockito.ArgumentMatchers.any;
22-
import static org.mockito.ArgumentMatchers.argThat;
23+
import static org.mockito.ArgumentMatchers.assertArg;
2324
import static org.mockito.Mockito.reset;
2425
import static org.mockito.Mockito.verify;
2526
import static org.mockito.Mockito.when;
2627

28+
import com.fasterxml.jackson.core.JsonGenerationException;
2729
import com.fasterxml.jackson.core.JsonLocation;
2830
import com.fasterxml.jackson.core.JsonProcessingException;
31+
import jakarta.ws.rs.ForbiddenException;
2932
import jakarta.ws.rs.core.Response;
3033
import jakarta.ws.rs.ext.ExceptionMapper;
34+
import java.io.IOException;
3135
import java.util.Optional;
3236
import java.util.stream.Stream;
37+
import org.apache.iceberg.exceptions.RuntimeIOException;
3338
import org.apache.polaris.core.exceptions.AlreadyExistsException;
3439
import org.apache.polaris.core.exceptions.CommitConflictException;
35-
import org.assertj.core.api.Assertions;
3640
import org.jboss.logmanager.Level;
3741
import org.junit.jupiter.api.BeforeEach;
3842
import org.junit.jupiter.api.Test;
@@ -67,35 +71,33 @@ public void testFullExceptionIsLogged(
6771

6872
verify(JBOSS_LOGGER)
6973
.logRaw(
70-
argThat(
74+
assertArg(
7175
record -> {
72-
if (record.getLevel() != level) {
73-
return false;
74-
}
76+
assertThat(record.getLevel()).isEqualTo(level);
7577

7678
String message = record.getMessage();
7779
if (message == null) {
78-
return false;
80+
return;
7981
}
8082

8183
Throwable error = record.getThrown();
8284
if (error == null) {
83-
return false;
85+
return;
8486
}
8587

86-
return message.contains(CAUSE)
87-
|| Optional.ofNullable(error.getCause())
88-
.map(Throwable::getMessage)
89-
.orElse("")
90-
.contains(CAUSE);
88+
assertThat(
89+
Optional.ofNullable(error.getCause())
90+
.map(Throwable::getMessage)
91+
.orElse(message))
92+
.contains(CAUSE);
9193
}));
9294
}
9395

9496
@Test
9597
public void testNamespaceException() {
9698
PolarisExceptionMapper mapper = new PolarisExceptionMapper();
9799
Response response = mapper.toResponse(new CommitConflictException("test"));
98-
Assertions.assertThat(response.getStatus()).isEqualTo(409);
100+
assertThat(response.getStatus()).isEqualTo(409);
99101
}
100102

101103
static Stream<Arguments> testFullExceptionIsLogged() {
@@ -105,21 +107,57 @@ static Stream<Arguments> testFullExceptionIsLogged() {
105107
Arguments.of(
106108
new IcebergExceptionMapper() {
107109
@Override
108-
Logger getLogger() {
110+
Logger getLoggerForExceptionLogging() {
109111
return new Slf4jLogger(JBOSS_LOGGER);
110112
}
111113
},
112114
new RuntimeException(MESSAGE, new RuntimeException(CAUSE)),
113115
Level.ERROR),
116+
Arguments.of(
117+
new IcebergExceptionMapper() {
118+
@Override
119+
Logger getLoggerForExceptionLogging() {
120+
return new Slf4jLogger(JBOSS_LOGGER);
121+
}
122+
},
123+
new RuntimeIOException(new IOException(new RuntimeException(CAUSE)), "%s", MESSAGE),
124+
Level.INFO),
125+
Arguments.of(
126+
new IcebergExceptionMapper() {
127+
@Override
128+
Logger getLoggerForExceptionLogging() {
129+
return new Slf4jLogger(JBOSS_LOGGER);
130+
}
131+
},
132+
new ForbiddenException(MESSAGE, new RuntimeException(CAUSE)),
133+
Level.DEBUG),
114134
Arguments.of(
115135
new IcebergJsonProcessingExceptionMapper() {
116136
@Override
117-
Logger getLogger() {
137+
Logger getLoggerForExceptionLogging() {
118138
return new Slf4jLogger(JBOSS_LOGGER);
119139
}
120140
},
121141
new TestJsonProcessingException(MESSAGE, null, new RuntimeException(CAUSE)),
122142
Level.DEBUG),
143+
Arguments.of(
144+
new IcebergJsonProcessingExceptionMapper() {
145+
@Override
146+
Logger getLoggerForExceptionLogging() {
147+
return new Slf4jLogger(JBOSS_LOGGER);
148+
}
149+
},
150+
new TestJsonProcessingException(MESSAGE, null, new RuntimeException(CAUSE)),
151+
Level.DEBUG),
152+
Arguments.of(
153+
new IcebergJsonProcessingExceptionMapper() {
154+
@Override
155+
Logger getLoggerForExceptionLogging() {
156+
return new Slf4jLogger(JBOSS_LOGGER);
157+
}
158+
},
159+
new JsonGenerationException(MESSAGE, new RuntimeException(CAUSE), null),
160+
Level.ERROR),
123161
Arguments.of(
124162
new PolarisExceptionMapper() {
125163
@Override

0 commit comments

Comments
 (0)