From eba2d4578676634f9fdb504c55b1eb3b8bdd8786 Mon Sep 17 00:00:00 2001 From: Tadgh Date: Thu, 8 Aug 2024 13:01:04 -0700 Subject: [PATCH] Resolve 6173 - Log unhandled Exceptions in RestfulServer (#6176) (#6205) * 6173 - Log unhandled Exceptions in RestfulServer. * Use placeholder for failed streams. * Starting test for server handling. * Got test working. * Fixed use of synchronized keyword. * Applied mvn spotless. --------- Co-authored-by: Kevin Dougan <72025369+KevinDougan@users.noreply.github.com> Co-authored-by: Michael Buckley --- .../fhir/rest/api/server/RequestDetails.java | 22 ++++++- .../uhn/fhir/rest/server/RestfulServer.java | 17 ++++++ .../rest/server/ServerConcurrencyTest.java | 58 +++++++++++++++++-- 3 files changed, 90 insertions(+), 7 deletions(-) diff --git a/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/api/server/RequestDetails.java b/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/api/server/RequestDetails.java index a141ca4664d..e3f6d852f70 100644 --- a/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/api/server/RequestDetails.java +++ b/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/api/server/RequestDetails.java @@ -20,6 +20,7 @@ package ca.uhn.fhir.rest.api.server; import ca.uhn.fhir.context.FhirContext; +import ca.uhn.fhir.i18n.Msg; import ca.uhn.fhir.interceptor.api.IInterceptorBroadcaster; import ca.uhn.fhir.rest.api.Constants; import ca.uhn.fhir.rest.api.RequestTypeEnum; @@ -30,6 +31,7 @@ import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.util.UrlUtil; import jakarta.servlet.http.HttpServletRequest; import jakarta.servlet.http.HttpServletResponse; +import org.apache.commons.lang3.ArrayUtils; import org.apache.commons.lang3.Validate; import org.hl7.fhir.instance.model.api.IBaseResource; import org.hl7.fhir.instance.model.api.IIdType; @@ -39,6 +41,7 @@ import java.io.InputStream; import java.io.Reader; import java.io.UnsupportedEncodingException; import java.nio.charset.Charset; +import java.nio.charset.StandardCharsets; import java.util.ArrayList; import java.util.Collections; import java.util.HashMap; @@ -50,6 +53,8 @@ import static org.apache.commons.lang3.StringUtils.isBlank; public abstract class RequestDetails { + public static final byte[] BAD_STREAM_PLACEHOLDER = + (Msg.code(2543) + "PLACEHOLDER WHEN READING FROM BAD STREAM").getBytes(StandardCharsets.UTF_8); private final StopWatch myRequestStopwatch; private IInterceptorBroadcaster myInterceptorBroadcaster; private String myTenantId; @@ -523,9 +528,22 @@ public abstract class RequestDetails { mySubRequest = theSubRequest; } - public final byte[] loadRequestContents() { + public final synchronized byte[] loadRequestContents() { if (myRequestContents == null) { - myRequestContents = getByteStreamRequestContents(); + // Initialize the byte array to a non-null value to avoid repeated calls to getByteStreamRequestContents() + // which can occur when getByteStreamRequestContents() throws an Exception + myRequestContents = ArrayUtils.EMPTY_BYTE_ARRAY; + try { + myRequestContents = getByteStreamRequestContents(); + } finally { + if (myRequestContents == null) { + // if reading the stream throws an exception, then our contents are still null, but the stream is + // dead. + // Set a placeholder value so nobody tries to read again. + myRequestContents = BAD_STREAM_PLACEHOLDER; + } + } + assert myRequestContents != null : "We must not re-read the stream."; } return getRequestContentsIfLoaded(); } diff --git a/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/RestfulServer.java b/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/RestfulServer.java index 842ef245e80..e2d4b4fb9e7 100644 --- a/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/RestfulServer.java +++ b/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/RestfulServer.java @@ -1038,6 +1038,9 @@ public class RestfulServer extends HttpServlet implements IRestfulServer myHeaders; + @RegisterExtension + LogbackTestExtension myLogbackTestExtension = new LogbackTestExtension(); @Test public void testExceptionClosingInputStream() throws IOException { - initRequestMocks(); + initRequestMocks("/Patient"); DelegatingServletInputStream inputStream = createMockPatientBodyServletInputStream(); inputStream.setExceptionOnClose(true); when(myRequest.getInputStream()).thenReturn(inputStream); @@ -78,7 +89,7 @@ public class ServerConcurrencyTest { @Test public void testExceptionClosingOutputStream() throws IOException { - initRequestMocks(); + initRequestMocks("/Patient"); when(myRequest.getInputStream()).thenReturn(createMockPatientBodyServletInputStream()); when(myResponse.getWriter()).thenReturn(myWriter); @@ -90,12 +101,44 @@ public class ServerConcurrencyTest { ); } - private void initRequestMocks() { + /** + * Exception thrown during SERVER_OUTGOING_FAILURE_OPERATIONOUTCOME + */ + @Test + void testExceptionThrownDuringExceptionHandler_bothExceptionsLogged() throws ServletException, IOException { + // given + initRequestMocks("/Patient?active=true"); + ourServer.getInterceptorService().registerAnonymousInterceptor(Pointcut.SERVER_OUTGOING_FAILURE_OPERATIONOUTCOME, (pointcut,params)->{ + throw new RuntimeException("MARKER_2: Exception during exception processing"); + }); + + // when + try { + ourServer.getRestfulServer().handleRequest(RequestTypeEnum.GET, myRequest, myResponse); + } catch (Throwable e) { + // eat any ex that escapes. We need to not depend on default logging. + } + + // then + // both exceptions should be logged. + LogbackTestExtensionAssert.assertThat(myLogbackTestExtension).hasErrorMessage("HAPI-2544"); + LogbackTestExtensionAssert.assertThat(myLogbackTestExtension).hasErrorMessage(SEARCH_TIMEOUT_ERROR); + } + + + private void initRequestMocks(String theURL) { myHeaders = new HashMap<>(); myHeaders.put(Constants.HEADER_CONTENT_TYPE, Constants.CT_FHIR_JSON_NEW); - when(myRequest.getRequestURI()).thenReturn("/Patient"); - when(myRequest.getRequestURL()).thenReturn(new StringBuffer(ourServer.getBaseUrl() + "/Patient")); + String relativeUri; + int endOfUri = theURL.indexOf("?"); + if (endOfUri >= 0) { + relativeUri = theURL.substring(0,endOfUri); + } else { + relativeUri = theURL; + } + when(myRequest.getRequestURI()).thenReturn(relativeUri); + when(myRequest.getRequestURL()).thenReturn(new StringBuffer(ourServer.getBaseUrl() + theURL)); when(myRequest.getHeader(any())).thenAnswer(t -> { String header = t.getArgument(0, String.class); String value = myHeaders.get(header); @@ -190,6 +233,11 @@ public class ServerConcurrencyTest { .setOperationOutcome(oo); } + @Search + public List search() throws InterruptedException { + throw new InterruptedException(SEARCH_TIMEOUT_ERROR); + } + @Override public Class getResourceType() {