Don't highlight AJAX requests

hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/server/Constants.java

@@ -41,6 +41,7 @@ public class Constants {
 	public static final String CT_OCTET_STREAM = "application/octet-stream";
 	public static final String CT_TEXT = "text/plain";
 	public static final String CT_TEXT_WITH_UTF8 = CT_TEXT + CHARSET_UTF8_CTSUFFIX;
+	public static final String CT_X_FORM_URLENCODED = "application/x-www-form-urlencoded";
 	public static final String CT_XML = "application/xml";
 	public static final String ENCODING_GZIP = "gzip";
 	public static final String EXTOP_VALIDATE = "$validate";
@@ -87,6 +88,7 @@ public class Constants {
 	public static final String HEADER_LAST_MODIFIED_LOWERCASE = HEADER_LAST_MODIFIED.toLowerCase();
 	public static final String HEADER_LOCATION = "Location";
 	public static final String HEADER_LOCATION_LC = HEADER_LOCATION.toLowerCase();
+	public static final String HEADER_ORIGIN = "Origin";
 	public static final String HEADER_PREFER = "Prefer";
 	public static final String HEADER_PREFER_RETURN = "return";
 	public static final String HEADER_PREFER_RETURN_MINIMAL = "minimal";
@@ -156,11 +158,10 @@ public class Constants {
 	public static final int STATUS_HTTP_500_INTERNAL_ERROR = 500;
 	public static final int STATUS_HTTP_501_NOT_IMPLEMENTED = 501;
 	public static final String TAG_SUBSETTED_CODE = "SUBSETTED";
+	
 	public static final String TAG_SUBSETTED_SYSTEM = "http://hl7.org/fhir/v3/ObservationValue";
 	public static final String URL_TOKEN_HISTORY = "_history";
-	
 	public static final String URL_TOKEN_METADATA = "metadata";
-	public static final String CT_X_FORM_URLENCODED = "application/x-www-form-urlencoded";
 
 	static {
 		Map<String, EncodingEnum> valToEncoding = new HashMap<String, EncodingEnum>();

hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/server/interceptor/LoggingInterceptor.java

@@ -30,10 +30,13 @@ import javax.servlet.ServletException;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.apache.commons.io.Charsets;
+import org.apache.commons.io.IOUtils;
 import org.apache.commons.lang3.StringUtils;
 import org.apache.commons.lang3.Validate;
 import org.apache.commons.lang3.text.StrLookup;
 import org.apache.commons.lang3.text.StrSubstitutor;
+import org.apache.http.util.EncodingUtils;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -87,6 +90,10 @@ import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException;
  * <td>The part of thre requesting URL that corresponds to the particular Servlet being called (see {@link HttpServletRequest#getServletPath()})</td>
  * </tr>
  * <tr>
+ * <td>${requestBodyFhir}</td>
+ * <td>The complete body of the request if the request has a FHIR content-type (this can be quite large!). Will emit an empty string if the content type is not a FHIR content type</td>
+ * </tr>
+ * <tr>
  * <td>${requestUrl}</td>
  * <td>The complete URL of the request</td>
  * </tr>
@@ -281,6 +288,20 @@ public class LoggingInterceptor extends InterceptorAdapter {
 				return myRequest.getRequestURL().toString();
 			} else if (theKey.equals("requestVerb")) {
 				return myRequest.getMethod();
+			} else if (theKey.equals("requestBodyFhir")) {
+				String contentType = myRequest.getContentType();
+				int colonIndex = contentType.indexOf(';');
+				if (colonIndex != -1) {
+					contentType = contentType.substring(0, colonIndex);
+				}
+				contentType = contentType.trim();
+				
+				EncodingEnum encoding = EncodingEnum.forContentType(contentType);
+				if (encoding != null) {
+					byte[] requestContents = myRequestDetails.loadRequestContents();
+					return new String(requestContents, Charsets.UTF_8);
+				}
+				return "";
 			}
 
 			return "!VAL!";

hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/server/interceptor/ResponseHighlighterInterceptor.java

@@ -1,6 +1,7 @@
 package ca.uhn.fhir.rest.server.interceptor;
 
 import static org.apache.commons.lang3.StringUtils.isBlank;
+import static org.apache.commons.lang3.StringUtils.isNotBlank;
 
 /*
  * #%L
@@ -24,6 +25,7 @@ import static org.apache.commons.lang3.StringUtils.isBlank;
 
 import java.io.IOException;
 import java.util.Arrays;
+import java.util.Enumeration;
 import java.util.List;
 import java.util.Set;
 
@@ -182,7 +184,7 @@ public class ResponseHighlighterInterceptor extends InterceptorAdapter {
 
 		return b.toString();
 	}
-
+private static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(ResponseHighlighterInterceptor.class);
 	@Override
 	public boolean outgoingResponse(RequestDetails theRequestDetails, IBaseResource theResponseObject, HttpServletRequest theServletRequest, HttpServletResponse theServletResponse) throws AuthenticationException {
 
@@ -207,10 +209,16 @@ public class ResponseHighlighterInterceptor extends InterceptorAdapter {
 		/*
 		 * It's an AJAX request, so no HTML
 		 */
-		String requestedWith = theServletRequest.getHeader("X-Requested-With");
+		if (!force && isNotBlank(theServletRequest.getHeader("X-Requested-With"))) {
-		if (!force && requestedWith != null) {
 			return super.outgoingResponse(theRequestDetails, theResponseObject, theServletRequest, theServletResponse);
 		}
+		/*
+		 * If the request has an Origin header, it is probably an AJAX request
+		 */
+		if (!force && isNotBlank(theServletRequest.getHeader(Constants.HEADER_ORIGIN))) {
+			return super.outgoingResponse(theRequestDetails, theResponseObject, theServletRequest, theServletResponse);
+		}
+		
 
 		/*
 		 * Not a GET

hapi-fhir-jpaserver-uhnfhirtest/src/main/java/ca/uhn/fhirtest/config/CommonConfig.java

@@ -13,7 +13,7 @@ public class CommonConfig {
 	 * Do some fancy logging to create a nice access log that has details about each incoming request.
 	 */
 	@Bean
-	public IServerInterceptor loggingInterceptor() {
+	public IServerInterceptor accessLoggingInterceptor() {
 		LoggingInterceptor retVal = new LoggingInterceptor();
 		retVal.setLoggerName("fhirtest.access");
 		retVal.setMessageFormat(
@@ -23,4 +23,16 @@ public class CommonConfig {
 		return retVal;
 	}
 
+	/**
+	 * Do some fancy logging to create a nice access log that has details about each incoming request.
+	 */
+	@Bean
+	public IServerInterceptor requestLoggingInterceptor() {
+		LoggingInterceptor retVal = new LoggingInterceptor();
+		retVal.setLoggerName("fhirtest.request");
+		retVal.setMessageFormat("Path[${servletPath}] ${requestBodyFhir}");
+		retVal.setLogExceptions(false);
+		return retVal;
+	}
+
 }

hapi-fhir-jpaserver-uhnfhirtest/src/main/resources/logback.xml

@@ -57,10 +57,34 @@
 		</encoder>
 	</appender>
 
+	<appender name="REQUEST" class="ch.qos.logback.core.rolling.RollingFileAppender">
+		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
+			<level>INFO</level>
+		</filter>
+		<file>${fhir.logdir}/request.log</file>
+		<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
+			<fileNamePattern>${fhir.logdir}/request.log.%i</fileNamePattern>
+			<minIndex>1</minIndex>
+			<maxIndex>3</maxIndex>
+		</rollingPolicy>
+		
+		<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
+			<maxFileSize>10MB</maxFileSize>
+		</triggeringPolicy>
+		<encoder>
+			<!-- [%file:%line] -->
+			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %msg%n</pattern>
+		</encoder>
+	</appender>
+
 	<logger name="fhirtest.access" level="INFO" additivity="false">
 		<appender-ref ref="ACCESS"/>
 	</logger>
 
+	<logger name="fhirtest.request" level="INFO" additivity="false">
+		<appender-ref ref="REQUEST"/>
+	</logger>
+
 	<logger name="ca.uhn.fhir.jpa.dao.FhirResourceDaoSubscriptionDstu2" additivity="true" level="debug">
 		<appender-ref ref="SUBSCRIPTION_FILE"/>
 	</logger>

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.junit.Assert.*;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertThat;
+import static org.junit.Assert.assertTrue;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
@@ -14,6 +16,9 @@ import java.util.concurrent.TimeUnit;
 import org.apache.commons.io.IOUtils;
 import org.apache.http.HttpResponse;
 import org.apache.http.client.methods.HttpGet;
+import org.apache.http.client.methods.HttpPost;
+import org.apache.http.entity.ContentType;
+import org.apache.http.entity.StringEntity;
 import org.apache.http.impl.client.CloseableHttpClient;
 import org.apache.http.impl.client.HttpClientBuilder;
 import org.apache.http.impl.conn.PoolingHttpClientConnectionManager;
@@ -38,12 +43,16 @@ import ca.uhn.fhir.model.dstu2.valueset.IdentifierUseEnum;
 import ca.uhn.fhir.model.primitive.DateDt;
 import ca.uhn.fhir.model.primitive.IdDt;
 import ca.uhn.fhir.model.primitive.UriDt;
+import ca.uhn.fhir.rest.annotation.Create;
 import ca.uhn.fhir.rest.annotation.IdParam;
 import ca.uhn.fhir.rest.annotation.Operation;
 import ca.uhn.fhir.rest.annotation.OperationParam;
 import ca.uhn.fhir.rest.annotation.Read;
 import ca.uhn.fhir.rest.annotation.RequiredParam;
+import ca.uhn.fhir.rest.annotation.ResourceParam;
 import ca.uhn.fhir.rest.annotation.Search;
+import ca.uhn.fhir.rest.api.MethodOutcome;
+import ca.uhn.fhir.rest.server.Constants;
 import ca.uhn.fhir.rest.server.IResourceProvider;
 import ca.uhn.fhir.rest.server.RestfulServer;
 import ca.uhn.fhir.rest.server.exceptions.InvalidRequestException;
@@ -68,7 +77,6 @@ public class LoggingInterceptorDstu2Test {
 		servlet.setInterceptors(Collections.singletonList(myInterceptor));
 	}
 
-
 	@Test
 	public void testException() throws Exception {
 
@@ -77,7 +85,7 @@ public class LoggingInterceptorDstu2Test {
 		assertTrue(interceptor.isLogExceptions());
 		interceptor.setErrorMessageFormat("ERROR - ${requestVerb} ${requestUrl}");
 		assertEquals("ERROR - ${requestVerb} ${requestUrl}", interceptor.getErrorMessageFormat());
-		
+
 		servlet.setInterceptors(Collections.singletonList((IServerInterceptor) interceptor));
 
 		Logger logger = mock(Logger.class);
@@ -90,7 +98,7 @@ public class LoggingInterceptorDstu2Test {
 		ArgumentCaptor<String> captor = ArgumentCaptor.forClass(String.class);
 		verify(logger, times(2)).info(captor.capture());
 		assertThat(captor.getAllValues().get(0), StringContains.containsString("read - Patient/EX"));
-		assertThat(captor.getAllValues().get(1), StringContains.containsString("ERROR - GET http://localhost:"+ourPort+"/Patient/EX"));
+		assertThat(captor.getAllValues().get(1), StringContains.containsString("ERROR - GET http://localhost:" + ourPort + "/Patient/EX"));
 	}
 
 	@Test
@@ -130,6 +138,31 @@ public class LoggingInterceptorDstu2Test {
 		assertEquals("extended-operation-instance - $everything - Patient/123", captor.getValue());
 	}
 
+	@Test
+	public void testCreate() throws Exception {
+
+		LoggingInterceptor interceptor = new LoggingInterceptor();
+		interceptor.setMessageFormat("${operationType} - ${operationName} - ${idOrResourceName} - ${requestBodyFhir}");
+		servlet.setInterceptors(Collections.singletonList((IServerInterceptor) interceptor));
+
+		Logger logger = mock(Logger.class);
+		interceptor.setLogger(logger);
+
+		Patient p = new Patient();
+		p.addIdentifier().setValue("VAL");
+		String input = ourCtx.newXmlParser().encodeResourceToString(p);
+		
+		HttpPost httpPost = new HttpPost("http://localhost:" + ourPort + "/Patient");
+		httpPost.setEntity(new StringEntity(input, ContentType.parse(Constants.CT_FHIR_XML+";charset=utf-8")));
+		
+		HttpResponse status = ourClient.execute(httpPost);
+		IOUtils.closeQuietly(status.getEntity().getContent());
+
+		ArgumentCaptor<String> captor = ArgumentCaptor.forClass(String.class);
+		verify(logger, times(1)).info(captor.capture());
+		assertEquals("create -  - Patient - <Patient xmlns=\"http://hl7.org/fhir\"><identifier><value value=\"VAL\"/></identifier></Patient>", captor.getValue());
+	}
+
 	@Test
 	public void testOperationOnServer() throws Exception {
 
@@ -205,7 +238,6 @@ public class LoggingInterceptorDstu2Test {
 		assertThat(captor.getValue(), StringContains.containsString("search-type - Patient - ?_id=1"));
 	}
 
-
 	@AfterClass
 	public static void afterClassClearContext() throws Exception {
 		ourServer.stop();
@@ -219,10 +251,10 @@ public class LoggingInterceptorDstu2Test {
 
 		ServletHandler proxyHandler = new ServletHandler();
 		servlet = new RestfulServer(ourCtx);
-		
+
 		servlet.setResourceProviders(new DummyPatientResourceProvider());
 		servlet.setPlainProviders(new PlainProvider());
-		
+
 		ServletHolder servletHolder = new ServletHolder(servlet);
 		proxyHandler.addServletWithMapping(servletHolder, "/*");
 		ourServer.setHandler(proxyHandler);
@@ -280,7 +312,7 @@ public class LoggingInterceptorDstu2Test {
 		 * Retrieve the resource by its identifier
 		 * 
 		 * @param theId
-		 *            The resource identity
+		 *           The resource identity
 		 * @return The resource
 		 */
 		@Read()
@@ -297,7 +329,7 @@ public class LoggingInterceptorDstu2Test {
 		 * Retrieve the resource by its identifier
 		 * 
 		 * @param theId
-		 *            The resource identity
+		 *           The resource identity
 		 * @return The resource
 		 */
 		@Search()
@@ -315,6 +347,11 @@ public class LoggingInterceptorDstu2Test {
 			return Patient.class;
 		}
 
+		@Create
+		public MethodOutcome create(@ResourceParam Patient thePatient) {
+			return new MethodOutcome(new IdDt("Patient/1"));
+		}
+		
 		@Operation(name = "$everything", idempotent = true)
 		public Bundle patientTypeOperation(@OperationParam(name = "start") DateDt theStart, @OperationParam(name = "end") DateDt theEnd) {
 
@@ -344,5 +381,5 @@ public class LoggingInterceptorDstu2Test {
 		}
 
 	}
-	
+
 }

hapi-fhir-structures-dstu2/src/test/java/ca/uhn/fhir/rest/server/interceptor/ResponseHighlightingInterceptorTest.java

@@ -31,7 +31,9 @@ import org.apache.http.client.methods.HttpGet;
 import org.apache.http.impl.client.CloseableHttpClient;
 import org.apache.http.impl.client.HttpClientBuilder;
 import org.apache.http.impl.conn.PoolingHttpClientConnectionManager;
+import org.ebaysf.web.cors.CORSFilter;
 import org.eclipse.jetty.server.Server;
+import org.eclipse.jetty.servlet.FilterHolder;
 import org.eclipse.jetty.servlet.ServletHandler;
 import org.eclipse.jetty.servlet.ServletHolder;
 import org.junit.AfterClass;
@@ -235,6 +237,43 @@ public class ResponseHighlightingInterceptorTest {
 
 	}
 	
+	@Test
+	public void testDontHighlightWhenOriginHeaderPresent() throws Exception {
+		ResponseHighlighterInterceptor ic = new ResponseHighlighterInterceptor();
+
+		HttpServletRequest req = mock(HttpServletRequest.class);
+		when(req.getHeaders(Constants.HEADER_ACCEPT)).thenAnswer(new Answer<Enumeration<String>>() {
+			@Override
+			public Enumeration<String> answer(InvocationOnMock theInvocation) throws Throwable {
+				return new ArrayEnumeration<String>("text/html,application/xhtml+xml,application/xml;q=0.9");
+			}
+		});
+		when(req.getHeader(Constants.HEADER_ORIGIN)).thenAnswer(new Answer<String>() {
+			@Override
+			public String answer(InvocationOnMock theInvocation) throws Throwable {
+				return "http://example.com";
+			}
+		});
+
+		HttpServletResponse resp = mock(HttpServletResponse.class);
+		StringWriter sw = new StringWriter();
+		when(resp.getWriter()).thenReturn(new PrintWriter(sw));
+
+		Patient resource = new Patient();
+		resource.addName().addFamily("FAMILY");
+
+		ServletRequestDetails reqDetails = new ServletRequestDetails();
+		reqDetails.setRequestType(RequestTypeEnum.GET);
+		HashMap<String, String[]> params = new HashMap<String, String[]>();
+		reqDetails.setParameters(params);
+		reqDetails.setServer(new RestfulServer(ourCtx));
+		reqDetails.setServletRequest(req);
+
+		// true means it decided to not handle the request..
+		assertTrue(ic.outgoingResponse(reqDetails, resource, req, resp));
+
+	}
+
 	/**
 	 * See #346
 	 */
@@ -482,6 +521,9 @@ public class ResponseHighlightingInterceptorTest {
 		ourServlet.setBundleInclusionRule(BundleInclusionRule.BASED_ON_RESOURCE_PRESENCE);
 		ServletHolder servletHolder = new ServletHolder(ourServlet);
 		proxyHandler.addServletWithMapping(servletHolder, "/*");
+		
+		proxyHandler.addFilterWithMapping(CORSFilter.class, "/*", 1);
+		
 		ourServer.setHandler(proxyHandler);
 		ourServer.start();
 

src/changes/changes.xml

@@ -90,6 +90,10 @@
 				which causes validator exceptions to be ignored, rather than causing
 				processing to be aborted.
 			</action>
+			<action type="add">
+				LoggingInterceptor on server has a new parameter 
+				<![CDATA[<code>${requestBodyFhir}</code>]]> which logs the entire request body.
+			</action>
 		</release>
 		<release version="1.5" date="2016-04-20">
 			<action type="fix" issue="339">
@@ -539,6 +543,10 @@
 				default to ISO-8859-1 encoding for URLs insetad of the UTF-8 encoding specified by
 				FHIR.
 			</action>
+			<action type="add">
+				ResponseHighlightingInterceptor now doesn't highlight if the request
+				has an Origin header, since this probably denotes an AJAX request.
+			</action>
 		</release>
 		<release version="1.4" date="2016-02-04">
 			<action type="add">