Skip to content

Commit b7f1cba

Browse files
at055612at055612
committed
gh-5090 Fix the way Auto Logger handles entity ser failure
1 parent 84959d9 commit b7f1cba

File tree

6 files changed

+103
-39
lines changed

6 files changed

+103
-39
lines changed

‎stroom-event-logging-rs/stroom-event-logging-rs-impl/src/main/java/stroom/event/logging/rs/impl/ContainerResourceInfo.java‎

Lines changed: 22 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,6 @@
1717
package stroom.event.logging.rs.impl;
1818

1919
import stroom.event.logging.api.EventActionDecorator;
20-
import stroom.event.logging.impl.LoggingConfig;
2120
import stroom.event.logging.rs.api.AutoLogged;
2221
import stroom.event.logging.rs.api.AutoLogged.OperationType;
2322
import stroom.security.api.SecurityContext;
@@ -103,13 +102,13 @@ public Class<? extends EventActionDecorator> getEventActionDecoratorClass() {
103102
public String getTypeId() {
104103
//If method annotation provided use that on its own
105104
if ((getMethod().getAnnotation(AutoLogged.class) != null) &&
106-
(!getMethod().getAnnotation(AutoLogged.class).typeId().equals(AutoLogged.ALLOCATE_AUTOMATICALLY))) {
105+
(!getMethod().getAnnotation(AutoLogged.class).typeId().equals(AutoLogged.ALLOCATE_AUTOMATICALLY))) {
107106
return getMethod().getAnnotation(AutoLogged.class).typeId();
108107
}
109108
String resourcePrefix = getResourceClass().getSimpleName();
110109
if ((getResourceClass().getAnnotation(AutoLogged.class) != null) &&
111-
(!getResourceClass().getAnnotation(AutoLogged.class).typeId()
112-
.equals(AutoLogged.ALLOCATE_AUTOMATICALLY))) {
110+
(!getResourceClass().getAnnotation(AutoLogged.class).typeId()
111+
.equals(AutoLogged.ALLOCATE_AUTOMATICALLY))) {
113112
resourcePrefix = getResourceClass().getAnnotation(AutoLogged.class).typeId();
114113
}
115114

@@ -118,7 +117,7 @@ public String getTypeId() {
118117

119118
public String getVerbFromAnnotations() {
120119
if ((getMethod().getAnnotation(AutoLogged.class) != null) &&
121-
(!getMethod().getAnnotation(AutoLogged.class).verb().equals(AutoLogged.ALLOCATE_AUTOMATICALLY))) {
120+
(!getMethod().getAnnotation(AutoLogged.class).verb().equals(AutoLogged.ALLOCATE_AUTOMATICALLY))) {
122121
return getMethod().getAnnotation(AutoLogged.class).verb();
123122
}
124123
return null;
@@ -192,27 +191,27 @@ private OperationType findOperationType(final Optional<OperationType> type,
192191
methodName, firstCamelCasePart));
193192

194193
if ("get".equals(firstCamelCasePart)
195-
|| "fetch".equals(firstCamelCasePart)
196-
|| "read".equals(firstCamelCasePart)
197-
|| "view".equals(firstCamelCasePart)) {
194+
|| "fetch".equals(firstCamelCasePart)
195+
|| "read".equals(firstCamelCasePart)
196+
|| "view".equals(firstCamelCasePart)) {
198197
return OperationType.VIEW;
199198
} else if ("create".equals(firstCamelCasePart)) {
200199
return OperationType.CREATE;
201200
} else if ("delete".equals(firstCamelCasePart)) {
202201
return OperationType.DELETE;
203202
} else if ("update".equals(firstCamelCasePart)
204-
|| "save".equals(firstCamelCasePart)
205-
|| "set".equals(firstCamelCasePart)) {
203+
|| "save".equals(firstCamelCasePart)
204+
|| "set".equals(firstCamelCasePart)) {
206205
return OperationType.UPDATE;
207206
} else if ("find".equals(firstCamelCasePart)
208-
|| "search".equals(firstCamelCasePart)
209-
|| "list".equals(firstCamelCasePart)) {
207+
|| "search".equals(firstCamelCasePart)
208+
|| "list".equals(firstCamelCasePart)) {
210209
return OperationType.SEARCH;
211210
} else if ("import".equals(firstCamelCasePart)
212-
|| "upload".equals(firstCamelCasePart)) {
211+
|| "upload".equals(firstCamelCasePart)) {
213212
return OperationType.IMPORT;
214213
} else if ("export".equals(firstCamelCasePart)
215-
|| "download".equals(firstCamelCasePart)) {
214+
|| "download".equals(firstCamelCasePart)) {
216215
return OperationType.EXPORT;
217216
} else if ("copy".equals(firstCamelCasePart)) {
218217
return OperationType.COPY;
@@ -222,7 +221,7 @@ private OperationType findOperationType(final Optional<OperationType> type,
222221
}
223222
}
224223

225-
public boolean shouldLog(final LoggingConfig config) {
224+
public boolean shouldLog() {
226225
final OperationType op = getOperationType();
227226
// if (OperationType.MANUALLY_LOGGED.equals(op)) {
228227
// LOGGER.debug("{}, not logging request", OperationType.MANUALLY_LOGGED);
@@ -232,7 +231,7 @@ public boolean shouldLog(final LoggingConfig config) {
232231
//// return true;
233232
// } else
234233
//
235-
if (OperationType.UNLOGGED.equals(op)) {
234+
if (op == OperationType.UNLOGGED) {
236235
LOGGER.debug("{}, not logging request", OperationType.UNLOGGED);
237236
return false;
238237
} else if (securityContext.isProcessingUser()) {
@@ -254,12 +253,12 @@ public boolean shouldLog(final LoggingConfig config) {
254253
@Override
255254
public String toString() {
256255
return "ContainerResourceInfo{" +
257-
"uri=" + requestContext.getUriInfo().getRequestUri() +
258-
", user=" + securityContext.getUserIdentityForAudit() +
259-
", requestContext=" + requestContext +
260-
", operationType=" + operationType +
261-
", eventActionDecoratorClass=" + eventActionDecoratorClass +
262-
", autologgerAnnotationPresent=" + autologgerAnnotationPresent +
263-
'}';
256+
"uri=" + requestContext.getUriInfo().getRequestUri() +
257+
", user=" + securityContext.getUserIdentityForAudit() +
258+
", requestContext=" + requestContext +
259+
", operationType=" + operationType +
260+
", eventActionDecoratorClass=" + eventActionDecoratorClass +
261+
", autologgerAnnotationPresent=" + autologgerAnnotationPresent +
262+
'}';
264263
}
265264
}

‎stroom-event-logging-rs/stroom-event-logging-rs-impl/src/main/java/stroom/event/logging/rs/impl/RequestEventLogImpl.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,7 @@ class RequestEventLogImpl implements RequestEventLog {
6464
@Override
6565
public void log(final RequestInfo requestInfo, @Nullable final Object responseEntity, final Throwable error) {
6666
final ContainerResourceInfo containerResourceInfo = requestInfo.getContainerResourceInfo();
67-
if (!containerResourceInfo.shouldLog(config)) {
67+
if (!containerResourceInfo.shouldLog()) {
6868
return;
6969
}
7070

‎stroom-event-logging-rs/stroom-event-logging-rs-impl/src/main/java/stroom/event/logging/rs/impl/RequestInfo.java‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,9 @@ public RequestInfo(final SecurityContext securityContext, final ContainerResourc
6161
}
6262

6363
public static boolean objectIsLoggable(final Object obj) {
64-
return obj != null && !obj.getClass().getName().startsWith("java.") && !(obj instanceof Collection);
64+
return obj != null
65+
&& !obj.getClass().getName().startsWith("java.")
66+
&& !(obj instanceof Collection);
6567
}
6668

6769
public RequestInfo(final SecurityContext securityContext,
@@ -105,8 +107,8 @@ private Object findBeforeOrAfterCallObj(final Object resource, final Object temp
105107
Object result = null;
106108

107109
//Only required for update and delete operations
108-
if (OperationType.UPDATE.equals(containerResourceInfo.getOperationType()) ||
109-
OperationType.DELETE.equals(containerResourceInfo.getOperationType())) {
110+
if (OperationType.UPDATE == containerResourceInfo.getOperationType() ||
111+
OperationType.DELETE == containerResourceInfo.getOperationType()) {
110112
try {
111113
final boolean templateHasAnId = template instanceof HasId ||
112114
template instanceof HasIntegerId || template instanceof HasUuid;

‎stroom-event-logging-rs/stroom-event-logging-rs-impl/src/main/java/stroom/event/logging/rs/impl/RestResourceAutoLoggerImpl.java‎

Lines changed: 46 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -25,19 +25,22 @@
2525
import stroom.util.json.JsonUtil;
2626
import stroom.util.logging.LambdaLogger;
2727
import stroom.util.logging.LambdaLoggerFactory;
28+
import stroom.util.logging.LogUtil;
2829
import stroom.util.shared.NullSafe;
2930

3031
import com.fasterxml.jackson.databind.ObjectMapper;
3132
import jakarta.inject.Inject;
3233
import jakarta.inject.Provider;
3334
import jakarta.inject.Singleton;
3435
import jakarta.servlet.http.HttpServletRequest;
36+
import jakarta.ws.rs.ServerErrorException;
3537
import jakarta.ws.rs.WebApplicationException;
3638
import jakarta.ws.rs.container.ContainerRequestContext;
3739
import jakarta.ws.rs.container.ResourceContext;
3840
import jakarta.ws.rs.container.ResourceInfo;
3941
import jakarta.ws.rs.core.Context;
4042
import jakarta.ws.rs.core.Response;
43+
import jakarta.ws.rs.core.Response.Status;
4144
import jakarta.ws.rs.core.UriInfo;
4245
import jakarta.ws.rs.ext.WriterInterceptorContext;
4346
import org.glassfish.jersey.message.MessageUtils;
@@ -120,8 +123,7 @@ public Response toResponse(final Throwable exception) {
120123

121124
ThreadLocalLogState.setLogged(false);
122125

123-
if (exception instanceof WebApplicationException) {
124-
final WebApplicationException wae = (WebApplicationException) exception;
126+
if (exception instanceof final WebApplicationException wae) {
125127
return wae.getResponse();
126128
} else {
127129
return delegatingExceptionMapperProvider.get().toResponse(exception);
@@ -131,16 +133,27 @@ public Response toResponse(final Throwable exception) {
131133
@Override
132134
public void aroundWriteTo(final WriterInterceptorContext writerInterceptorContext)
133135
throws WebApplicationException {
136+
// When we come in here, the resource method will have completed successfully,
137+
// so we can intercept its returned value (the entity) before jakarta.ws.rs
138+
// serialises it to json (or some other mime type).
139+
// This means we can include the returned entity in the audit log event.
140+
Exception exception = null;
134141
try {
135142
writerInterceptorContext.proceed();
136143
} catch (final Exception ex) {
137-
LOGGER.error("Error in Java RS filter chain processing.", ex);
144+
// This is either an error serialising the entity or in another interceptor in the chain.
145+
// Swallow and save the ex, so we can log the failure
146+
LOGGER.error("Error in Jakarta RS filter chain processing, which is likely " +
147+
"a problem serialising the resource's response entity. " +
148+
"entityType: {}, entity: {}, exceptionMessage: {}",
149+
writerInterceptorContext.getType(),
150+
writerInterceptorContext.getEntity(),
151+
LogUtil.exceptionMessage(ex), ex);
152+
exception = ex;
138153
}
139154

140-
final Object object = request.getAttribute(REQUEST_LOG_INFO_PROPERTY);
141-
if (object != null) {
142-
final RequestInfo requestInfo = (RequestInfo) object;
143-
if (OperationType.MANUALLY_LOGGED.equals(requestInfo.getContainerResourceInfo().getOperationType())) {
155+
if (request.getAttribute(REQUEST_LOG_INFO_PROPERTY) instanceof final RequestInfo requestInfo) {
156+
if (OperationType.MANUALLY_LOGGED == requestInfo.getContainerResourceInfo().getOperationType()) {
144157
if (!ThreadLocalLogState.hasLogged()) {
145158
LOGGER.debug("Expected manual logging to have happened: "
146159
+ NullSafe.get(requestInfo.getContainerResourceInfo(),
@@ -149,12 +162,34 @@ public void aroundWriteTo(final WriterInterceptorContext writerInterceptorContex
149162
UriInfo::getRequestUri));
150163
}
151164
} else {
152-
requestEventLogProvider.get().log(requestInfo, writerInterceptorContext.getEntity());
165+
// The log() method will check if logging is required, e.g. for UNLOGGED
166+
final Object entity = writerInterceptorContext.getEntity();
167+
if (LOGGER.isDebugEnabled()) {
168+
LOGGER.debug("aroundWriteTo() - type: {}, entity: {}, exceptionMessage: {}",
169+
writerInterceptorContext.getType(),
170+
entity,
171+
LogUtil.exceptionMessage(exception));
172+
}
173+
if (exception != null) {
174+
// Log it as a failure
175+
requestEventLogProvider.get()
176+
.log(requestInfo, entity, exception);
177+
} else {
178+
requestEventLogProvider.get()
179+
.log(requestInfo, entity);
180+
}
153181
}
154182
request.setAttribute(REQUEST_LOG_INFO_PROPERTY, null);
155183
}
156184

157185
ThreadLocalLogState.setLogged(false);
186+
187+
// Now we have done our audit logging, we can re-throw any error so the caller gets it
188+
if (exception instanceof final WebApplicationException wae) {
189+
throw wae;
190+
} else if (exception != null) {
191+
throw new ServerErrorException(LogUtil.exceptionMessage(exception), Status.INTERNAL_SERVER_ERROR);
192+
}
158193
}
159194

160195
@Override
@@ -167,9 +202,10 @@ public void filter(final ContainerRequestContext context) throws IOException {
167202
context,
168203
loggingConfigProvider.get().isLogEveryRestCallEnabled());
169204

170-
if (containerResourceInfo.shouldLog(loggingConfigProvider.get())) {
205+
if (containerResourceInfo.shouldLog()) {
171206
if (context.hasEntity()) {
172-
final RequestEntityCapturingInputStream stream = new RequestEntityCapturingInputStream(resourceInfo,
207+
final RequestEntityCapturingInputStream stream = new RequestEntityCapturingInputStream(
208+
resourceInfo,
173209
context.getEntityStream(),
174210
OBJECT_MAPPER,
175211
MessageUtils.getCharset(context.getMediaType()));
@@ -191,5 +227,4 @@ public void filter(final ContainerRequestContext context) throws IOException {
191227
void setResourceContext(final ResourceContext resourceContext) {
192228
this.resourceContext = resourceContext;
193229
}
194-
195230
}

‎stroom-query/stroom-query-language/src/test/java/stroom/query/language/functions/TestVal.java‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,29 @@
1010

1111
public class TestVal {
1212

13+
// @TestFactory
14+
// Stream<DynamicTest> testSerDeSer() {
15+
// return TestUtil.buildDynamicTestStream()
16+
// .withInputTypes(Val.class, Class.class)
17+
// .withOutputType(Val.class)
18+
// .withTestFunction(tesatCase -> {
19+
// final Val val = tesatCase.getInput()._1();
20+
// final Class clazz = tesatCase.getInput()._2();
21+
// final Val val2 = TestUtil.testSerialisation(val, clazz);
22+
// return val2;
23+
// })
24+
// .withAssertions(tuple2ValTestOutcome -> {
25+
// final Val input = tuple2ValTestOutcome.getInput()._1();
26+
// final Val output = tuple2ValTestOutcome.getActualOutput();
27+
// Assertions.assertThat(output)
28+
// .isEqualTo(input);
29+
// })
30+
// .addCase(Tuple.of(ValString.create("foo"), ValString.class), null)
31+
// .addCase(Tuple.of(ValLong.create(123L), ValLong.class), null)
32+
// .build();
33+
// }
34+
35+
1336
@TestFactory
1437
Stream<DynamicTest> testNullSafeCreate() {
1538
return TestUtil.buildDynamicTestStream()

‎stroom-query/stroom-query-language/src/test/java/stroom/query/language/functions/TestValString.java‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,11 @@
1313

1414
class TestValString {
1515

16+
// @Test
17+
// void testSerDeser() {
18+
// TestUtil.testSerialisation(ValString.create("foo"), ValString.class);
19+
// }
20+
1621
@TestFactory
1722
Stream<DynamicTest> testHasNumericValue() {
1823
return TestUtil.buildDynamicTestStream()
@@ -144,7 +149,7 @@ Stream<DynamicTest> testToLong() {
144149
// Duration parsed then returned as millis
145150
.addCase(
146151
ValString.create(duration.toString()),
147-
duration.toMillis())
152+
duration.toMillis())
148153
.build();
149154
}
150155

0 commit comments

Comments
 (0)