diff --git a/service/src/main/java/org/whispersystems/textsecuregcm/WhisperServerService.java b/service/src/main/java/org/whispersystems/textsecuregcm/WhisperServerService.java index 9877b69e4..fc53c4369 100644 --- a/service/src/main/java/org/whispersystems/textsecuregcm/WhisperServerService.java +++ b/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 webSocketEnvironment, WebSocketEnvironment 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()); diff --git a/service/src/main/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListener.java b/service/src/main/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListener.java index 001351594..c00ea33e5 100644 --- a/service/src/main/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListener.java +++ b/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 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(); - } } diff --git a/service/src/main/java/org/whispersystems/textsecuregcm/util/logging/LoggingUnhandledExceptionMapper.java b/service/src/main/java/org/whispersystems/textsecuregcm/util/logging/LoggingUnhandledExceptionMapper.java new file mode 100644 index 000000000..e4accb904 --- /dev/null +++ b/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 { + + @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) ; + } + +} diff --git a/service/src/main/java/org/whispersystems/textsecuregcm/util/logging/UriInfoUtil.java b/service/src/main/java/org/whispersystems/textsecuregcm/util/logging/UriInfoUtil.java new file mode 100644 index 000000000..bd94d2c18 --- /dev/null +++ b/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(); + } +} diff --git a/service/src/test/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListenerTest.java b/service/src/test/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListenerTest.java index c6be54ccb..6bfcd09b3 100644 --- a/service/src/test/java/org/whispersystems/textsecuregcm/metrics/MetricsRequestEventListenerTest.java +++ b/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); diff --git a/service/src/test/java/org/whispersystems/textsecuregcm/util/logging/LoggingUnhandledExceptionMapperTest.java b/service/src/test/java/org/whispersystems/textsecuregcm/util/logging/LoggingUnhandledExceptionMapperTest.java new file mode 100644 index 000000000..83c1ecbef --- /dev/null +++ b/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 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(); + } + } +} diff --git a/service/src/test/java/org/whispersystems/textsecuregcm/util/logging/UriInfoUtilTest.java b/service/src/test/java/org/whispersystems/textsecuregcm/util/logging/UriInfoUtilTest.java new file mode 100644 index 000000000..a5800dfa7 --- /dev/null +++ b/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)); + } + +}