diff --git a/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptor.java b/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptor.java index 883c101811c..729ab9d9cb2 100644 --- a/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptor.java +++ b/hapi-fhir-server/src/main/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptor.java @@ -113,17 +113,13 @@ import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails; * ${exceptionMessage} * Applies only to an error message: The message from {@link Exception#getMessage()} * - * - */ - -/* - * TODO: implement this, but it needs the logging to happen at the end * * ${processingTimeMillis} * The number of milliseconds spent processing this request * - + * */ + public class LoggingInterceptor extends InterceptorAdapter { private static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(LoggingInterceptor.class); @@ -169,7 +165,7 @@ public class LoggingInterceptor extends InterceptorAdapter { StrLookup lookup = new MyLookup(theRequestDetails.getServletRequest(), theRequestDetails); StrSubstitutor subs = new StrSubstitutor(lookup, "${", "}", '\\'); - // Actuall log the line + // Actually log the line String line = subs.replace(myMessageFormat); myLogger.info(line); } diff --git a/hapi-fhir-structures-dstu2/src/test/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptorDstu2Test.java b/hapi-fhir-structures-dstu2/src/test/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptorDstu2Test.java index ef284ce1781..572c8d3709f 100644 --- a/hapi-fhir-structures-dstu2/src/test/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptorDstu2Test.java +++ b/hapi-fhir-structures-dstu2/src/test/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptorDstu2Test.java @@ -1,6 +1,8 @@ package ca.uhn.fhir.rest.server.interceptor; +import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.matchesPattern; +import static org.hamcrest.Matchers.startsWith; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertThat; import static org.junit.Assert.assertTrue; @@ -149,6 +151,28 @@ public class LoggingInterceptorDstu2Test { assertEquals("read - - Patient/1 - ", captor.getValue()); } + @Test + public void testRequestProcessingTime() throws Exception { + + LoggingInterceptor interceptor = new LoggingInterceptor(); + interceptor.setMessageFormat("${operationType} - ${processingTimeMillis}"); + servlet.setInterceptors(Collections.singletonList((IServerInterceptor) interceptor)); + + Logger logger = mock(Logger.class); + interceptor.setLogger(logger); + + HttpGet httpGet = new HttpGet("http://localhost:" + ourPort + "/Patient/1"); + + HttpResponse status = ourClient.execute(httpGet); + IOUtils.closeQuietly(status.getEntity().getContent()); + + ArgumentCaptor captor = ArgumentCaptor.forClass(String.class); + verify(logger, timeout(1000).times(1)).info(captor.capture()); + assertThat(captor.getValue(), startsWith("read - ")); + int millis = Integer.parseInt(captor.getValue().substring("read - ".length())); + assertThat(millis, greaterThan(1)); + } + @Test public void testProcessingTime() throws Exception { ourDelayMs = 110; diff --git a/src/changes/changes.xml b/src/changes/changes.xml index b17cdd4d815..d61e72af780 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -342,6 +342,13 @@ This property causes references to unknown resources in created/updated resources to have a placeholder target resource automatically created. + + The server LoggingInterceptor has had a variable called + processingTimeMillis]]> which logs the number + of milliseconds the server took to process a given request since + HAPI FHIR 2.5, but this was not documented. This variable has now been + documented as a part of the available features. +