Added selectively logging content for requests [#739]

comixed · Nov 11, 2021 · 735aea6 · 735aea6
1 parent 3d9f6b2
commit 735aea6
Show file tree

Hide file tree

Showing 24 changed files with 318 additions and 65 deletions.
diff --git a/comixed-auditlog/src/main/java/org/comixedproject/auditlog/AuditableEndpoint.java b/comixed-auditlog/src/main/java/org/comixedproject/auditlog/AuditableEndpoint.java
@@ -18,10 +18,24 @@
 
 package org.comixedproject.auditlog;
 
+import java.lang.annotation.*;
+
 /**
  * <code>AuditableEndpoint</code> is used to indicate that a method is to be audited whenever it's
  * invoked.
  *
  * @author Darryl L. Pierce
  */
-public @interface AuditableEndpoint {}
+@Target({ElementType.METHOD})
+@Retention(RetentionPolicy.RUNTIME)
+@Documented
+@Inherited
+public @interface AuditableEndpoint {
+  public boolean logRequest() default false;
+
+  public Class requestView() default Class.class;
+
+  public boolean logResponse() default false;
+
+  public Class responseView() default Class.class;
+}
diff --git a/comixed-auditlog/src/main/java/org/comixedproject/auditlog/AuditableEndpointAspect.java b/comixed-auditlog/src/main/java/org/comixedproject/auditlog/AuditableEndpointAspect.java
@@ -27,6 +27,7 @@
 import org.aspectj.lang.ProceedingJoinPoint;
 import org.aspectj.lang.annotation.Around;
 import org.aspectj.lang.annotation.Aspect;
+import org.aspectj.lang.reflect.MethodSignature;
 import org.comixedproject.model.auditlog.WebAuditLogEntry;
 import org.comixedproject.service.auditlog.WebAuditLogService;
 import org.springframework.beans.factory.annotation.Autowired;
@@ -58,6 +59,8 @@ public class AuditableEndpointAspect {
   public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
     Throwable thrownError = null;
     Object response = null;
+    final MethodSignature signature = (MethodSignature) joinPoint.getSignature();
+    final var annotation = signature.getMethod().getAnnotation(AuditableEndpoint.class);
 
     final var started = new Date();
     try {
@@ -80,8 +83,27 @@ public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
     entry.setMethod(request.getMethod());
     entry.setStartTime(started);
     entry.setEndTime(ended);
-    entry.setRequestContent(
-        new String(((ContentCachingRequestWrapper) request).getContentAsByteArray()));
+    if (annotation.logRequest()) {
+      log.trace("Logging request content");
+      if (annotation.requestView() != Class.class) {
+        entry.setRequestContent(
+            this.objectMapper.writerWithView(annotation.requestView()).writeValueAsString(request));
+      } else {
+        entry.setRequestContent(
+            new String(((ContentCachingRequestWrapper) request).getContentAsByteArray()));
+      }
+    }
+    if (annotation.logResponse()) {
+      log.trace("Logging response content");
+      if (annotation.responseView() != Class.class) {
+        entry.setResponseContent(
+            this.objectMapper
+                .writerWithView(annotation.responseView())
+                .writeValueAsString(response));
+      } else {
+        entry.setResponseContent(this.objectMapper.writeValueAsString(response));
+      }
+    }
 
     if (thrownError != null) {
       log.debug("Storing method exception stacktrace");

diff --git a/comixed-auditlog/src/test/java/org/comixedproject/auditlog/AuditableEndpointAspectTest.java b/comixed-auditlog/src/test/java/org/comixedproject/auditlog/AuditableEndpointAspectTest.java
@@ -18,13 +18,17 @@
 
 package org.comixedproject.auditlog;
 
-import static junit.framework.TestCase.assertNotNull;
-import static junit.framework.TestCase.assertSame;
+import static junit.framework.TestCase.*;
 
+import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
+import com.fasterxml.jackson.databind.ObjectWriter;
+import java.security.Principal;
 import org.aspectj.lang.ProceedingJoinPoint;
+import org.aspectj.lang.reflect.MethodSignature;
 import org.comixedproject.model.auditlog.WebAuditLogEntry;
 import org.comixedproject.service.auditlog.WebAuditLogService;
+import org.comixedproject.views.View;
 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
@@ -36,25 +40,137 @@
 
 @RunWith(MockitoJUnitRunner.class)
 public class AuditableEndpointAspectTest {
-  private static final byte[] TEST_RESPONSE_OBJECT = "JSON content".getBytes();
+  private static final String TEST_OBJECT_AS_STRING = "This is a JSON-encoded object";
+  private static final String TEST_OBJECT_AS_STRING_NO_VIEW =
+      "This is the encoded object without a view";
+  private static final String TEST_EMAIL = "reader@comixedproject.org";
 
   @InjectMocks private AuditableEndpointAspect auditableEndpointAspect;
   @Mock private WebAuditLogService webAuditLogService;
   @Mock private ProceedingJoinPoint proceedingJoinPoint;
   @Mock private Object response;
-  @Captor private ArgumentCaptor<WebAuditLogEntry> restAuditLogEntryArgumentCaptor;
   @Mock private WebAuditLogEntry savedEntry;
   @Mock private ObjectMapper objectMapper;
+  @Mock private ObjectWriter objectWriter;
   @Mock private ContentCachingRequestWrapper requestWrapper;
+  @Mock private Principal principal;
+  @Mock private MethodSignature methodSignature;
+
+  @Captor private ArgumentCaptor<WebAuditLogEntry> restAuditLogEntryArgumentCaptor;
 
   @Before
-  public void setUp() {
+  public void setUp() throws JsonProcessingException {
     RequestContextHolder.setRequestAttributes(new ServletRequestAttributes(requestWrapper));
-    Mockito.when(requestWrapper.getContentAsByteArray()).thenReturn(TEST_RESPONSE_OBJECT);
+    Mockito.when(requestWrapper.getContentAsByteArray())
+        .thenReturn(TEST_OBJECT_AS_STRING_NO_VIEW.getBytes());
+    Mockito.when(objectMapper.writeValueAsString(Mockito.any()))
+        .thenReturn(TEST_OBJECT_AS_STRING_NO_VIEW);
+    Mockito.when(objectMapper.writerWithView(View.GenericObjectView.class))
+        .thenReturn(objectWriter);
+    Mockito.when(objectWriter.writeValueAsString(Mockito.any())).thenReturn(TEST_OBJECT_AS_STRING);
+    Mockito.when(proceedingJoinPoint.getSignature()).thenReturn(methodSignature);
+  }
+
+  @Test
+  public void testAroundLogRequest() throws Throwable {
+    Mockito.when(methodSignature.getMethod())
+        .thenReturn(AuditableTestClass.class.getMethod("methodWithLoggedRequest"));
+    Mockito.when(webAuditLogService.save(restAuditLogEntryArgumentCaptor.capture()))
+        .thenReturn(savedEntry);
+    Mockito.when(proceedingJoinPoint.proceed()).thenReturn(response);
+
+    final Object result = auditableEndpointAspect.around(proceedingJoinPoint);
+
+    assertNotNull(result);
+    assertSame(response, result);
+
+    final WebAuditLogEntry entry = restAuditLogEntryArgumentCaptor.getValue();
+    assertNotNull(entry);
+    assertNull(entry.getResponseContent());
+    assertEquals(TEST_OBJECT_AS_STRING_NO_VIEW, entry.getRequestContent());
+
+    Mockito.verify(webAuditLogService, Mockito.times(1))
+        .save(restAuditLogEntryArgumentCaptor.getValue());
+    Mockito.verify(proceedingJoinPoint, Mockito.times(1)).proceed();
+  }
+
+  @Test
+  public void testAroundLogRequestWithView() throws Throwable {
+    Mockito.when(methodSignature.getMethod())
+        .thenReturn(AuditableTestClass.class.getMethod("methodWithLoggedRequestWithView"));
+    Mockito.when(webAuditLogService.save(restAuditLogEntryArgumentCaptor.capture()))
+        .thenReturn(savedEntry);
+    Mockito.when(proceedingJoinPoint.proceed()).thenReturn(response);
+
+    final Object result = auditableEndpointAspect.around(proceedingJoinPoint);
+
+    assertNotNull(result);
+    assertSame(response, result);
+
+    final WebAuditLogEntry entry = restAuditLogEntryArgumentCaptor.getValue();
+    assertNotNull(entry);
+    assertNull(entry.getResponseContent());
+    assertEquals(TEST_OBJECT_AS_STRING, entry.getRequestContent());
+
+    Mockito.verify(webAuditLogService, Mockito.times(1))
+        .save(restAuditLogEntryArgumentCaptor.getValue());
+    Mockito.verify(proceedingJoinPoint, Mockito.times(1)).proceed();
+    Mockito.verify(objectMapper, Mockito.times(1)).writerWithView(View.GenericObjectView.class);
+  }
+
+  @Test
+  public void testAroundLogResponse() throws Throwable {
+    Mockito.when(methodSignature.getMethod())
+        .thenReturn(AuditableTestClass.class.getMethod("methodWithLoggedResponse"));
+    Mockito.when(webAuditLogService.save(restAuditLogEntryArgumentCaptor.capture()))
+        .thenReturn(savedEntry);
+    Mockito.when(proceedingJoinPoint.proceed()).thenReturn(response);
+
+    final Object result = auditableEndpointAspect.around(proceedingJoinPoint);
+
+    assertNotNull(result);
+    assertSame(response, result);
+
+    final WebAuditLogEntry entry = restAuditLogEntryArgumentCaptor.getValue();
+    assertNotNull(entry);
+    assertNull(entry.getRequestContent());
+    assertEquals(TEST_OBJECT_AS_STRING_NO_VIEW, entry.getResponseContent());
+
+    Mockito.verify(webAuditLogService, Mockito.times(1))
+        .save(restAuditLogEntryArgumentCaptor.getValue());
+    Mockito.verify(proceedingJoinPoint, Mockito.times(1)).proceed();
+  }
+
+  @Test
+  public void testAroundLogResponseWithView() throws Throwable {
+    Mockito.when(methodSignature.getMethod())
+        .thenReturn(AuditableTestClass.class.getMethod("methodWithLoggedResponseWithView"));
+    Mockito.when(webAuditLogService.save(restAuditLogEntryArgumentCaptor.capture()))
+        .thenReturn(savedEntry);
+    Mockito.when(proceedingJoinPoint.proceed()).thenReturn(response);
+
+    final Object result = auditableEndpointAspect.around(proceedingJoinPoint);
+
+    assertNotNull(result);
+    assertSame(response, result);
+
+    final WebAuditLogEntry entry = restAuditLogEntryArgumentCaptor.getValue();
+    assertNotNull(entry);
+    assertNull(entry.getRequestContent());
+    assertEquals(TEST_OBJECT_AS_STRING, entry.getResponseContent());
+
+    Mockito.verify(webAuditLogService, Mockito.times(1))
+        .save(restAuditLogEntryArgumentCaptor.getValue());
+    Mockito.verify(proceedingJoinPoint, Mockito.times(1)).proceed();
+    Mockito.verify(objectMapper, Mockito.times(1)).writerWithView(View.GenericObjectView.class);
   }
 
   @Test
-  public void testAround() throws Throwable {
+  public void testAroundContainsUserPrincipal() throws Throwable {
+    Mockito.when(methodSignature.getMethod())
+        .thenReturn(AuditableTestClass.class.getMethod("methodWithNoLogging"));
+    Mockito.when(requestWrapper.getUserPrincipal()).thenReturn(principal);
+    Mockito.when(principal.getName()).thenReturn(TEST_EMAIL);
     Mockito.when(webAuditLogService.save(restAuditLogEntryArgumentCaptor.capture()))
         .thenReturn(savedEntry);
     Mockito.when(proceedingJoinPoint.proceed()).thenReturn(response);
@@ -64,8 +180,50 @@ public void testAround() throws Throwable {
     assertNotNull(result);
     assertSame(response, result);
 
+    final WebAuditLogEntry entry = restAuditLogEntryArgumentCaptor.getValue();
+    assertNotNull(entry);
+    assertEquals(TEST_EMAIL, entry.getEmail());
+
     Mockito.verify(webAuditLogService, Mockito.times(1))
         .save(restAuditLogEntryArgumentCaptor.getValue());
     Mockito.verify(proceedingJoinPoint, Mockito.times(1)).proceed();
   }
+
+  @Test(expected = Exception.class)
+  public void testAroundLogException() throws Throwable {
+    Mockito.when(methodSignature.getMethod())
+        .thenReturn(AuditableTestClass.class.getMethod("methodWithNoLogging"));
+    Mockito.when(webAuditLogService.save(restAuditLogEntryArgumentCaptor.capture()))
+        .thenReturn(savedEntry);
+    Mockito.when(proceedingJoinPoint.proceed()).thenThrow(Exception.class);
+
+    try {
+      auditableEndpointAspect.around(proceedingJoinPoint);
+    } finally {
+      final WebAuditLogEntry entry = restAuditLogEntryArgumentCaptor.getValue();
+      assertNotNull(entry);
+      assertNotNull(entry.getException());
+
+      Mockito.verify(webAuditLogService, Mockito.times(1))
+          .save(restAuditLogEntryArgumentCaptor.getValue());
+      Mockito.verify(proceedingJoinPoint, Mockito.times(1)).proceed();
+    }
+  }
+
+  private class AuditableTestClass {
+    @AuditableEndpoint
+    public void methodWithNoLogging() {}
+
+    @AuditableEndpoint(logRequest = true)
+    public void methodWithLoggedRequest() {}
+
+    @AuditableEndpoint(logRequest = true, requestView = View.GenericObjectView.class)
+    public void methodWithLoggedRequestWithView() {}
+
+    @AuditableEndpoint(logResponse = true)
+    public void methodWithLoggedResponse() {}
+
+    @AuditableEndpoint(logResponse = true, responseView = View.GenericObjectView.class)
+    public void methodWithLoggedResponseWithView() {}
+  }
 }
diff --git a/comixed-auditlog/src/test/resources/mockito-extensions/org.mockito.plugins.MockMaker b/comixed-auditlog/src/test/resources/mockito-extensions/org.mockito.plugins.MockMaker
@@ -0,0 +1 @@
+mock-maker-inline
diff --git a/...c/main/java/org/comixedproject/messaging/comicbooks/PublishProcessComicsStatusAction.java b/...c/main/java/org/comixedproject/messaging/comicbooks/PublishProcessComicsStatusAction.java
@@ -38,6 +38,6 @@ public class PublishProcessComicsStatusAction extends AbstractPublishAction<Proc
 
   @Override
   public void publish(final ProcessComicStatus subject) throws PublishingException {
-    this.doPublish(PROCESS_COMIC_STATE_TOPIC, subject, View.GenericResponseView.class);
+    this.doPublish(PROCESS_COMIC_STATE_TOPIC, subject, View.GenericObjectView.class);
   }
 }
diff --git a/comixed-model/src/main/java/org/comixedproject/model/messaging/batch/ProcessComicStatus.java b/comixed-model/src/main/java/org/comixedproject/model/messaging/batch/ProcessComicStatus.java
@@ -46,32 +46,32 @@ public class ProcessComicStatus {
   public static final String PROCESSED_COMICS = "add-comic-state.processed-comics";
 
   @JsonProperty("active")
-  @JsonView(View.GenericResponseView.class)
+  @JsonView(View.GenericObjectView.class)
   @Getter
   @Setter
   private boolean active = true;
 
   @JsonProperty("started")
-  @JsonView(View.GenericResponseView.class)
+  @JsonView(View.GenericObjectView.class)
   @JsonFormat(shape = JsonFormat.Shape.NUMBER_INT)
   @Getter
   @Setter
   private Date started;
 
   @JsonProperty("stepName")
-  @JsonView(View.GenericResponseView.class)
+  @JsonView(View.GenericObjectView.class)
   @Getter
   @Setter
   private String stepName;
 
   @JsonProperty("total")
-  @JsonView(View.GenericResponseView.class)
+  @JsonView(View.GenericObjectView.class)
   @Getter
   @Setter
   private long total;
 
   @JsonProperty("processed")
-  @JsonView(View.GenericResponseView.class)
+  @JsonView(View.GenericObjectView.class)
   @Getter
   @Setter
   private long processed;

diff --git a/comixed-model/src/main/java/org/comixedproject/model/net/GenericResponse.java b/comixed-model/src/main/java/org/comixedproject/model/net/GenericResponse.java
@@ -34,7 +34,7 @@
 @AllArgsConstructor
 public class GenericResponse {
   @JsonProperty("success")
-  @JsonView(View.GenericResponseView.class)
+  @JsonView(View.GenericObjectView.class)
   @NonNull
   @Getter
   private Boolean success;

diff --git a/comixed-model/src/main/java/org/comixedproject/views/View.java b/comixed-model/src/main/java/org/comixedproject/views/View.java
@@ -26,7 +26,7 @@
  */
 public interface View {
   /** Used when returning the generic response. */
-  public interface GenericResponseView {}
+  public interface GenericObjectView {}
 
   /** Used when retrieving the list of comic formats. */
   public interface ComicFormatList {}

diff --git a/comixed-opds/src/main/java/org/comixedproject/opds/rest/OPDSCollectionController.java b/comixed-opds/src/main/java/org/comixedproject/opds/rest/OPDSCollectionController.java
@@ -59,7 +59,7 @@ public class OPDSCollectionController {
    * @throws OPDSException if the collection type is unknown
    */
   @GetMapping(value = "/opds/collections/{type}", produces = MediaType.APPLICATION_XML_VALUE)
-  @AuditableEndpoint
+  @AuditableEndpoint(logResponse = true)
   @PreAuthorize("hasRole('READER')")
   @ResponseBody
   public OPDSNavigationFeed getCollectionFeed(
@@ -129,7 +129,7 @@ private OPDSNavigationFeed createCollectionFeed(
    * @throws OPDSException if the collection type is unknown
    */
   @GetMapping(value = "/opds/collections/{type}/{name}", produces = MediaType.APPLICATION_XML_VALUE)
-  @AuditableEndpoint
+  @AuditableEndpoint(logResponse = true)
   @PreAuthorize("hasRole('READER')")
   @ResponseBody
   public OPDSAcquisitionFeed getEntriesForCollectionFeed(

diff --git a/comixed-opds/src/main/java/org/comixedproject/opds/rest/OPDSLibraryController.java b/comixed-opds/src/main/java/org/comixedproject/opds/rest/OPDSLibraryController.java
@@ -49,7 +49,7 @@ public class OPDSLibraryController {
    * @return the feed
    */
   @GetMapping(value = "/opds", produces = MediaType.APPLICATION_XML_VALUE)
-  @AuditableEndpoint
+  @AuditableEndpoint(logResponse = true)
   @PreAuthorize("hasRole('READER')")
   @ResponseBody
   public OPDSNavigationFeed getRootFeed() {
@@ -76,7 +76,7 @@ public OPDSNavigationFeed getRootFeed() {
    * @return the feed
    */
   @GetMapping(value = "/opds/library", produces = MediaType.APPLICATION_XML_VALUE)
-  @AuditableEndpoint
+  @AuditableEndpoint(logResponse = true)
   @PreAuthorize("hasRole('READER')")
   @ResponseBody
   public OPDSNavigationFeed getLibraryFeed() {