From 022b5566488b0050cde0519b34d8a1501ad2c5df Mon Sep 17 00:00:00 2001
From: James Agnew <jamesagnew@gmail.com>
Date: Thu, 31 Aug 2017 10:12:15 -0400
Subject: [PATCH] Add documentation for logginginterceptor processing time
 variable (which already worked, but wasn't documented)

---
 .../interceptor/LoggingInterceptor.java       | 10 +++-----
 .../LoggingInterceptorDstu2Test.java          | 24 +++++++++++++++++++
 src/changes/changes.xml                       |  7 ++++++
 3 files changed, 34 insertions(+), 7 deletions(-)

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;
  * <td>${exceptionMessage}</td>
  * <td>Applies only to an error message: The message from {@link Exception#getMessage()}</td>
  * </tr>
- * </table>
- */
-
-/*
- * TODO: implement this, but it needs the logging to happen at the end
  * <tr>
  * <td>${processingTimeMillis}</td>
  * <td>The number of milliseconds spent processing this request</td>
  * </tr>
-
+ * </table>
  */
+
 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<String> 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.
 			</action>
+			<action type="add">
+				The server LoggingInterceptor has had a variable called
+				<![CDATA[<code>processingTimeMillis</code>]]> 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.
+			</action>
 		</release>
 		<release version="2.5" date="2017-06-08">
 			<action type="fix">