Add request path and user agent to unhandled exception logging

service/src/main/java/org/whispersystems/textsecuregcm/WhisperServerService.java

@@ -191,6 +191,7 @@ import org.whispersystems.textsecuregcm.util.Constants;
 import org.whispersystems.textsecuregcm.util.DynamoDbFromConfig;
 import org.whispersystems.textsecuregcm.util.HostnameUtil;
 import org.whispersystems.textsecuregcm.util.TorExitNodeManager;
+import org.whispersystems.textsecuregcm.util.logging.LoggingUnhandledExceptionMapper;
 import org.whispersystems.textsecuregcm.websocket.AuthenticatedConnectListener;
 import org.whispersystems.textsecuregcm.websocket.DeadLetterHandler;
 import org.whispersystems.textsecuregcm.websocket.ProvisioningConnectListener;
@@ -625,18 +626,21 @@ public class WhisperServerService extends Application<WhisperServerConfiguration
   }
 
   private void registerExceptionMappers(Environment environment, WebSocketEnvironment<Account> webSocketEnvironment, WebSocketEnvironment<Account> provisioningEnvironment) {
+    environment.jersey().register(new LoggingUnhandledExceptionMapper());
     environment.jersey().register(new IOExceptionMapper());
     environment.jersey().register(new RateLimitExceededExceptionMapper());
     environment.jersey().register(new InvalidWebsocketAddressExceptionMapper());
     environment.jersey().register(new DeviceLimitExceededExceptionMapper());
     environment.jersey().register(new RetryLaterExceptionMapper());
 
+    webSocketEnvironment.jersey().register(new LoggingUnhandledExceptionMapper());
     webSocketEnvironment.jersey().register(new IOExceptionMapper());
     webSocketEnvironment.jersey().register(new RateLimitExceededExceptionMapper());
     webSocketEnvironment.jersey().register(new InvalidWebsocketAddressExceptionMapper());
     webSocketEnvironment.jersey().register(new DeviceLimitExceededExceptionMapper());
     webSocketEnvironment.jersey().register(new RetryLaterExceptionMapper());
 
+    provisioningEnvironment.jersey().register(new LoggingUnhandledExceptionMapper());
     provisioningEnvironment.jersey().register(new IOExceptionMapper());
     provisioningEnvironment.jersey().register(new RateLimitExceededExceptionMapper());
     provisioningEnvironment.jersey().register(new InvalidWebsocketAddressExceptionMapper());

service/src/main/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListener.java

@@ -12,9 +12,9 @@ import com.vdurmont.semver4j.SemverException;
 import io.micrometer.core.instrument.MeterRegistry;
 import io.micrometer.core.instrument.Metrics;
 import io.micrometer.core.instrument.Tag;
-import org.glassfish.jersey.server.ExtendedUriInfo;
 import org.glassfish.jersey.server.monitoring.RequestEvent;
 import org.glassfish.jersey.server.monitoring.RequestEventListener;
+import org.whispersystems.textsecuregcm.util.logging.UriInfoUtil;
 import org.whispersystems.textsecuregcm.util.ua.ClientPlatform;
 import org.whispersystems.textsecuregcm.util.ua.UnrecognizedUserAgentException;
 import org.whispersystems.textsecuregcm.util.ua.UserAgent;
@@ -71,7 +71,7 @@ public class MetricsRequestEventListener implements RequestEventListener {
         if (event.getType() == RequestEvent.Type.FINISHED) {
             if (!event.getUriInfo().getMatchedTemplates().isEmpty()) {
                 final List<Tag> tags = new ArrayList<>(5);
-                tags.add(Tag.of(PATH_TAG, getPathTemplate(event.getUriInfo())));
+                tags.add(Tag.of(PATH_TAG, UriInfoUtil.getPathTemplate(event.getUriInfo())));
                 tags.add(Tag.of(STATUS_CODE_TAG, String.valueOf(event.getContainerResponse().getStatus())));
                 tags.add(Tag.of(TRAFFIC_SOURCE_TAG, trafficSource.name().toLowerCase()));
 
@@ -149,14 +149,4 @@ public class MetricsRequestEventListener implements RequestEventListener {
         }
     }
 
-    @VisibleForTesting
-    static String getPathTemplate(final ExtendedUriInfo uriInfo) {
-        final StringBuilder pathBuilder = new StringBuilder();
-
-        for (int i = uriInfo.getMatchedTemplates().size() - 1; i >= 0; i--) {
-            pathBuilder.append(uriInfo.getMatchedTemplates().get(i).getTemplate());
-        }
-
-        return pathBuilder.toString();
-    }
 }

service/src/main/java/org/whispersystems/textsecuregcm/util/logging/LoggingUnhandledExceptionMapper.java

@@ -0,0 +1,62 @@
+/*
+ * Copyright 2013-2021 Signal Messenger, LLC
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+package org.whispersystems.textsecuregcm.util.logging;
+
+import com.google.common.annotations.VisibleForTesting;
+import io.dropwizard.jersey.errors.LoggingExceptionMapper;
+import javax.servlet.http.HttpServletRequest;
+import javax.ws.rs.core.Context;
+import org.glassfish.jersey.server.ExtendedUriInfo;
+import org.slf4j.Logger;
+import org.whispersystems.textsecuregcm.util.ua.UnrecognizedUserAgentException;
+import org.whispersystems.textsecuregcm.util.ua.UserAgent;
+import org.whispersystems.textsecuregcm.util.ua.UserAgentUtil;
+
+public class LoggingUnhandledExceptionMapper extends LoggingExceptionMapper<Throwable> {
+
+  @Context
+  private HttpServletRequest request;
+
+  @Context
+  private ExtendedUriInfo uriInfo;
+
+  public LoggingUnhandledExceptionMapper() {
+    super();
+  }
+
+  @VisibleForTesting
+  LoggingUnhandledExceptionMapper(final Logger logger) {
+    super(logger);
+  }
+
+  @Override
+  protected String formatLogMessage(final long id, final Throwable exception) {
+    String requestMethod = "unknown method";
+    String userAgent = "missing";
+    String requestPath = "/{unknown path}";
+    try {
+      // request and uriInfo shouldn’t be `null`, but it is technically possible
+      requestMethod = request.getMethod();
+      requestPath = UriInfoUtil.getPathTemplate(uriInfo);
+      userAgent = request.getHeader("user-agent");
+
+      // streamline the user-agent if it is recognized
+      final UserAgent ua = UserAgentUtil.parseUserAgentString(userAgent);
+      userAgent = String.format("%s %s", ua.getPlatform(), ua.getVersion());
+    } catch (final UnrecognizedUserAgentException ignored) {
+
+    } catch (final Exception e) {
+      logger.warn("Unexpected exception getting request details", e);
+    }
+
+    return String.format("%s at %s %s (%s)",
+        super.formatLogMessage(id, exception),
+        requestMethod,
+        requestPath,
+        userAgent) ;
+  }
+
+}

service/src/main/java/org/whispersystems/textsecuregcm/util/logging/UriInfoUtil.java

@@ -0,0 +1,21 @@
+/*
+ * Copyright 2013-2021 Signal Messenger, LLC
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+package org.whispersystems.textsecuregcm.util.logging;
+
+import org.glassfish.jersey.server.ExtendedUriInfo;
+
+public class UriInfoUtil {
+
+  public static String getPathTemplate(final ExtendedUriInfo uriInfo) {
+      final StringBuilder pathBuilder = new StringBuilder();
+
+      for (int i = uriInfo.getMatchedTemplates().size() - 1; i >= 0; i--) {
+          pathBuilder.append(uriInfo.getMatchedTemplates().get(i).getTemplate());
+      }
+
+      return pathBuilder.toString();
+  }
+}

service/src/test/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListenerTest.java

@@ -124,18 +124,6 @@ public class MetricsRequestEventListenerTest {
         // assertTrue(tags.contains(Tag.of(UserAgentTagUtil.VERSION_TAG, "4.53.7")));
     }
 
-    @Test
-    public void testGetPathTemplate() {
-        final UriTemplate firstComponent = new UriTemplate("/first");
-        final UriTemplate secondComponent = new UriTemplate("/second");
-        final UriTemplate thirdComponent = new UriTemplate("/{param}/{moreDifferentParam}");
-
-        final ExtendedUriInfo uriInfo = mock(ExtendedUriInfo.class);
-        when(uriInfo.getMatchedTemplates()).thenReturn(Arrays.asList(thirdComponent, secondComponent, firstComponent));
-
-        assertEquals("/first/second/{param}/{moreDifferentParam}", MetricsRequestEventListener.getPathTemplate(uriInfo));
-    }
-
     @Test
     public void testActualRouteMessageSuccess() throws InvalidProtocolBufferException {
         MetricsApplicationEventListener applicationEventListener = mock(MetricsApplicationEventListener.class);

service/src/test/java/org/whispersystems/textsecuregcm/util/logging/LoggingUnhandledExceptionMapperTest.java

@@ -0,0 +1,100 @@
+/*
+ * Copyright 2013-2021 Signal Messenger, LLC
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+package org.whispersystems.textsecuregcm.util.logging;
+
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.matches;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.reset;
+import static org.mockito.Mockito.spy;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.verifyNoInteractions;
+
+import io.dropwizard.testing.junit5.DropwizardExtensionsSupport;
+import io.dropwizard.testing.junit5.ResourceExtension;
+import java.util.stream.Stream;
+import javax.ws.rs.GET;
+import javax.ws.rs.Path;
+import javax.ws.rs.PathParam;
+import javax.ws.rs.core.Response;
+import org.glassfish.jersey.test.grizzly.GrizzlyWebTestContainerFactory;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.extension.ExtendWith;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.Arguments;
+import org.junit.jupiter.params.provider.MethodSource;
+import org.slf4j.Logger;
+
+@ExtendWith(DropwizardExtensionsSupport.class)
+class LoggingUnhandledExceptionMapperTest {
+
+  private static final Logger logger = mock(Logger.class);
+
+  private static LoggingUnhandledExceptionMapper exceptionMapper = spy(new LoggingUnhandledExceptionMapper(logger));
+
+  private static final ResourceExtension resources = ResourceExtension.builder()
+      .addProvider(exceptionMapper)
+      .setTestContainerFactory(new GrizzlyWebTestContainerFactory())
+      .addResource(new TestController())
+      .build();
+
+  @BeforeEach
+  void setup() {
+    reset(exceptionMapper);
+  }
+
+  @ParameterizedTest
+  @MethodSource
+  void testExceptionMapper(final boolean expectException, final String targetPath, final String loggedPath, final String userAgentHeader,
+      final String userAgentLog) {
+
+    resources.getJerseyTest()
+        .target(targetPath)
+        .request()
+        .header("User-Agent", userAgentHeader)
+        .get();
+
+    if (expectException) {
+
+      verify(exceptionMapper, times(1)).toResponse(any(Exception.class));
+      verify(logger, times(1)).error(matches(String.format(".* at GET %s \\(%s\\)", loggedPath, userAgentLog)), any(Exception.class));
+
+    } else {
+      verifyNoInteractions(exceptionMapper);
+    }
+  }
+
+  static Stream<Arguments> testExceptionMapper() {
+    return Stream.of(
+        Arguments.of(false, "/v1/test/no-exception", "/v1/test/no-exception", null, null, null),
+        Arguments.of(true, "/v1/test/unhandled-runtime-exception", "/v1/test/unhandled-runtime-exception", "Signal-Android/5.1.2 Android/30", "ANDROID 5.1.2"),
+        Arguments.of(true, "/v1/test/unhandled-runtime-exception/1/and/two", "/v1/test/unhandled-runtime-exception/\\{parameter1\\}/and/\\{parameter2\\}", "Signal-iOS/5.10.2 iOS/14.1", "IOS 5.10.2")
+    );
+  }
+
+  @Path("/v1/test")
+  public static class TestController {
+
+    @GET
+    @Path("/no-exception")
+    public Response testNoException() {
+      return Response.ok().build();
+    }
+
+    @GET
+    @Path("/unhandled-runtime-exception")
+    public Response testUnhandledException() {
+      throw new RuntimeException();
+    }
+
+    @GET
+    @Path("/unhandled-runtime-exception/{parameter1}/and/{parameter2}")
+    public Response testUnhandledExceptionWithPathParameter(@PathParam("parameter1") String parameter1, @PathParam("parameter2") String parameter2) {
+      throw new RuntimeException();
+    }
+  }
+}

service/src/test/java/org/whispersystems/textsecuregcm/util/logging/UriInfoUtilTest.java

@@ -0,0 +1,31 @@
+/*
+ * Copyright 2013-2021 Signal Messenger, LLC
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+package org.whispersystems.textsecuregcm.util.logging;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+import java.util.Arrays;
+import org.glassfish.jersey.server.ExtendedUriInfo;
+import org.glassfish.jersey.uri.UriTemplate;
+import org.junit.jupiter.api.Test;
+
+class UriInfoUtilTest {
+
+  @Test
+  void testGetPathTemplate() {
+    final UriTemplate firstComponent = new UriTemplate("/first");
+    final UriTemplate secondComponent = new UriTemplate("/second");
+    final UriTemplate thirdComponent = new UriTemplate("/{param}/{moreDifferentParam}");
+
+    final ExtendedUriInfo uriInfo = mock(ExtendedUriInfo.class);
+    when(uriInfo.getMatchedTemplates()).thenReturn(Arrays.asList(thirdComponent, secondComponent, firstComponent));
+
+    assertEquals("/first/second/{param}/{moreDifferentParam}", UriInfoUtil.getPathTemplate(uriInfo));
+  }
+
+}