Fix NPE in LoggingInterceptor

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

@@ -1,5 +1,7 @@
 package ca.uhn.fhir.rest.server.interceptor;
 
+import static org.apache.commons.lang3.StringUtils.isNotBlank;
+
 import java.io.IOException;
 
 /*
@@ -31,12 +33,10 @@ 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;
 
@@ -58,15 +58,18 @@ import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException;
  * </tr>
  * <tr>
  * <td>${idOrResourceName}</td>
- * <td>The resource ID associated with this request, or the resource name if the request applies to a type but not an instance, or "" otherwise</td>
+ * <td>The resource ID associated with this request, or the resource name if the request applies to a type but not an
+ * instance, or "" otherwise</td>
  * </tr>
  * <tr>
  * <td>${operationName}</td>
- * <td>If the request is an extended operation (e.g. "$validate") this value will be the operation name, or "" otherwise</td>
+ * <td>If the request is an extended operation (e.g. "$validate") this value will be the operation name, or ""
+ * otherwise</td>
  * </tr>
  * <tr>
  * <td>${operationType}</td>
- * <td>A code indicating the operation type for this request, e.g. "read", "history-instance", "extended-operation-instance", etc.)</td>
+ * <td>A code indicating the operation type for this request, e.g. "read", "history-instance",
+ * "extended-operation-instance", etc.)</td>
  * </tr>
  * <tr>
  * <td>${remoteAddr}</td>
@@ -74,7 +77,8 @@ import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException;
  * </tr>
  * <tr>
  * <td>${requestHeader.XXXX}</td>
- * <td>The value of the HTTP request header named XXXX. For example, a substitution variable named "${requestHeader.x-forwarded-for} will yield the value of the first header named "x-forwarded-for
+ * <td>The value of the HTTP request header named XXXX. For example, a substitution variable named
+ * "${requestHeader.x-forwarded-for} will yield the value of the first header named "x-forwarded-for
  * ", or "" if none.</td>
  * </tr>
  * <tr>
@@ -83,15 +87,18 @@ import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException;
  * </tr>
  * <tr>
  * <td>${responseEncodingNoDefault}</td>
- * <td>The encoding format requested by the client via the _format parameter or the Accept header. Value will be "json" or "xml", or "" if the client did not explicitly request a format</td>
+ * <td>The encoding format requested by the client via the _format parameter or the Accept header. Value will be "json"
+ * or "xml", or "" if the client did not explicitly request a format</td>
  * </tr>
  * <tr>
  * <td>${servletPath}</td>
- * <td>The part of thre requesting URL that corresponds to the particular Servlet being called (see {@link HttpServletRequest#getServletPath()})</td>
+ * <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>
+ * <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>
@@ -124,8 +131,7 @@ public class LoggingInterceptor extends InterceptorAdapter {
 	}
 
 	@Override
-	public boolean handleException(RequestDetails theRequestDetails, BaseServerResponseException theException, HttpServletRequest theServletRequest, HttpServletResponse theServletResponse)
+	public boolean handleException(RequestDetails theRequestDetails, BaseServerResponseException theException, HttpServletRequest theServletRequest, HttpServletResponse theServletResponse) throws ServletException, IOException {
-			throws ServletException, IOException {
 		if (myLogExceptions) {
 			// Perform any string substitutions from the message format
 			StrLookup<?> lookup = new MyLookup(theServletRequest, theException, theRequestDetails);
@@ -187,7 +193,8 @@ public class LoggingInterceptor extends InterceptorAdapter {
 	}
 
 	/**
-	 * Sets the message format itself. See the {@link LoggingInterceptor class documentation} for information on the format
+	 * Sets the message format itself. See the {@link LoggingInterceptor class documentation} for information on the
+	 * format
 	 */
 	public void setMessageFormat(String theMessageFormat) {
 		Validate.notBlank(theMessageFormat, "Message format can not be null/empty");
@@ -290,6 +297,7 @@ public class LoggingInterceptor extends InterceptorAdapter {
 				return myRequest.getMethod();
 			} else if (theKey.equals("requestBodyFhir")) {
 				String contentType = myRequest.getContentType();
+				if (isNotBlank(contentType)) {
 					int colonIndex = contentType.indexOf(';');
 					if (colonIndex != -1) {
 						contentType = contentType.substring(0, colonIndex);
@@ -301,6 +309,7 @@ public class LoggingInterceptor extends InterceptorAdapter {
 						byte[] requestContents = myRequestDetails.loadRequestContents();
 						return new String(requestContents, Charsets.UTF_8);
 					}
+				}
 				return "";
 			}
 

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

@@ -103,10 +103,12 @@ public class ServletRequestDetails extends RequestDetails {
 				String contentEncoding = myServletRequest.getHeader(Constants.HEADER_CONTENT_ENCODING);
 				if ("gzip".equals(contentEncoding)) {
 					ourLog.debug("Uncompressing (GZip) incoming content");
+					if (requestContents.length > 0) {
 						GZIPInputStream gis = new GZIPInputStream(new ByteArrayInputStream(requestContents));
 						requestContents = IOUtils.toByteArray(gis);
 					}
 				}
+			}
 			
 			return requestContents;
 		} catch (IOException e) {

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/PathAndRef.java

@@ -1,5 +1,25 @@
 package ca.uhn.fhir.jpa.dao;
 
+/*
+ * #%L
+ * HAPI FHIR JPA Server
+ * %%
+ * Copyright (C) 2014 - 2016 University Health Network
+ * %%
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ * 
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ * #L%
+ */
+
 public class PathAndRef {
 
 	private final String myPath;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3Test.java

@@ -9,6 +9,7 @@ import static org.hamcrest.Matchers.endsWith;
 import static org.hamcrest.Matchers.greaterThan;
 import static org.hamcrest.Matchers.hasItem;
 import static org.hamcrest.Matchers.not;
+import static org.hamcrest.Matchers.startsWith;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertNotEquals;
@@ -32,6 +33,9 @@ import java.util.Map;
 import java.util.Set;
 
 import org.apache.commons.lang3.RandomStringUtils;
+import org.apache.http.client.methods.HttpPost;
+import org.apache.http.entity.ContentType;
+import org.apache.http.entity.StringEntity;
 import org.hamcrest.Matchers;
 import org.hamcrest.core.StringContains;
 import org.hl7.fhir.dstu3.model.BaseResource;
@@ -118,7 +122,6 @@ public class FhirResourceDaoDstu3Test extends BaseJpaDstu3Test {
 		TestUtil.clearAllStaticFieldsForUnitTest();
 	}
 
-
 	private void assertGone(IIdType theId) {
 		try {
 			assertNotGone(theId);
@@ -240,7 +243,6 @@ public class FhirResourceDaoDstu3Test extends BaseJpaDstu3Test {
 		}
 	}
 
-	
 	@Test
 	public void testChoiceParamDate() {
 		Observation o2 = new Observation();

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/dstu3/ResourceProviderQuestionnaireResponseDstu3Test.java

@@ -1,12 +1,23 @@
 package ca.uhn.fhir.jpa.provider.dstu3;
 
 import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.startsWith;
+import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertThat;
 import static org.junit.Assert.fail;
 
+import java.io.IOException;
 import java.util.Collection;
 
+import org.apache.commons.io.IOUtils;
+import org.apache.http.client.ClientProtocolException;
+import org.apache.http.client.methods.CloseableHttpResponse;
+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.hl7.fhir.dstu3.model.DecimalType;
+import org.hl7.fhir.dstu3.model.IdType;
 import org.hl7.fhir.dstu3.model.Patient;
 import org.hl7.fhir.dstu3.model.Questionnaire;
 import org.hl7.fhir.dstu3.model.Questionnaire.QuestionnaireItemType;
@@ -17,6 +28,7 @@ import org.junit.AfterClass;
 import org.junit.Before;
 import org.junit.Test;
 
+import ca.uhn.fhir.rest.server.Constants;
 import ca.uhn.fhir.rest.server.exceptions.UnprocessableEntityException;
 import ca.uhn.fhir.rest.server.interceptor.RequestValidatingInterceptor;
 import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails;
@@ -100,4 +112,76 @@ public class ResourceProviderQuestionnaireResponseDstu3Test extends BaseResource
 		}
 	}
 	
+	@Test
+	public void testSaveQuestionnaire() throws Exception {
+		String input = "<QuestionnaireResponse xmlns=\"http://hl7.org/fhir\">\n" + 
+				"    <status value=\"completed\"/>\n" + 
+				"    <authored value=\"2016-05-03T13:05:20-04:00\"/>\n" + 
+				"    <item>\n" + 
+				"        <linkId value=\"breast-feeding-intention\"/>\n" + 
+				"        <text value=\"Breast Feeding Intention:\"/>\n" + 
+				"        <answer>\n" + 
+				"            <valueCoding>\n" + 
+				"                <system value=\"http://example.org/codesystem-breastfeeding-intention\"/>\n" + 
+				"                <code value=\"true\"/>\n" + 
+				"                <display value=\"Mother wants to provide formula exclusively\"/>\n" + 
+				"            </valueCoding>\n" + 
+				"        </answer>\n" + 
+				"    </item>\n" + 
+				"    <item>\n" + 
+				"        <linkId value=\"breast-feeding-education\"/>\n" + 
+				"        <text value=\"Answer if not exclusive BM:\"/>\n" + 
+				"        <answer>\n" + 
+				"            <valueCoding>\n" + 
+				"                <system value=\"http://example.org/codesystem-breastfeeding-education\"/>\n" + 
+				"                <code value=\"true\"/>\n" + 
+				"                <display value=\"Mother not given comprehensive education per protocol\"/>\n" + 
+				"            </valueCoding>\n" + 
+				"        </answer>\n" + 
+				"    </item>\n" + 
+				"    <item>\n" + 
+				"        <linkId value=\"breast-feeding-exclusion\"/>\n" + 
+				"        <text value=\"Exclusion Criteria:\"/>\n" + 
+				"        <answer>\n" + 
+				"            <valueCoding>\n" + 
+				"                <system value=\"http://example.org/codesystem-breastfeeding-exclusion\"/>\n" + 
+				"                <code value=\"true\"/>\n" + 
+				"                <display\n" + 
+				"                    value=\"Maternal use of drugs of abuse, antimetabolites, chemotherapeutic agents, or radioisotopes\"\n" + 
+				"                />\n" + 
+				"            </valueCoding>\n" + 
+				"        </answer>\n" + 
+				"    </item>\n" + 
+				"</QuestionnaireResponse>";
+		
+		HttpPost post = new HttpPost(ourServerBase + "/QuestionnaireResponse");
+		post.setEntity(new StringEntity(input, ContentType.create(Constants.CT_FHIR_XML, "UTF-8")));
+		CloseableHttpResponse response = ourHttpClient.execute(post);
+		final IdType id2;
+		try {
+			String responseString = IOUtils.toString(response.getEntity().getContent());
+			ourLog.info("Response: {}", responseString);
+			assertEquals(201, response.getStatusLine().getStatusCode());
+			String newIdString = response.getFirstHeader(Constants.HEADER_LOCATION_LC).getValue();
+			assertThat(newIdString, startsWith(ourServerBase + "/QuestionnaireResponse/"));
+			id2 = new IdType(newIdString);
+		} finally {
+			IOUtils.closeQuietly(response);
+		}
+
+		HttpGet get = new HttpGet(ourServerBase + "/QuestionnaireResponse/" + id2.getIdPart() + "?_format=xml&_pretty=true");
+		response = ourHttpClient.execute(get);
+		try {
+			String responseString = IOUtils.toString(response.getEntity().getContent());
+			ourLog.info("Response: {}", responseString);
+			assertThat(responseString, containsString("Exclusion Criteria"));
+		} finally {
+			IOUtils.closeQuietly(response);
+		}
+		
+		
+		
+	}
+
+
 }

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

@@ -30,7 +30,7 @@ public class CommonConfig {
 	public IServerInterceptor requestLoggingInterceptor() {
 		LoggingInterceptor retVal = new LoggingInterceptor();
 		retVal.setLoggerName("fhirtest.request");
-		retVal.setMessageFormat("Path[${servletPath}] ${requestBodyFhir}");
+		retVal.setMessageFormat("${requestVerb} ${servletPath} -\n${requestBodyFhir}");
 		retVal.setLogExceptions(false);
 		return retVal;
 	}

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

@@ -73,7 +73,7 @@
 		</triggeringPolicy>
 		<encoder>
 			<!-- [%file:%line] -->
-			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %msg%n</pattern>
+			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %msg%n</pattern>
 		</encoder>
 	</appender>
 

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

@@ -70,11 +70,13 @@ public class LoggingInterceptorDstu2Test {
 	private static Server ourServer;
 	private static RestfulServer servlet;
 	private IServerInterceptor myInterceptor;
+	private static Exception ourThrowException;
 
 	@Before
 	public void before() {
 		myInterceptor = mock(IServerInterceptor.class);
 		servlet.setInterceptors(Collections.singletonList(myInterceptor));
+		ourThrowException = null;
 	}
 
 	@Test
@@ -139,7 +141,48 @@ public class LoggingInterceptorDstu2Test {
 	}
 
 	@Test
-	public void testCreate() throws Exception {
+	public void testRequestBodyRead() 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);
+
+		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, times(1)).info(captor.capture());
+		assertEquals("read -  - Patient/1 - ", captor.getValue());
+	}
+
+	@Test
+	public void testRequestBodyReadWithContentTypeHeader() 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);
+
+		HttpGet httpGet = new HttpGet("http://localhost:" + ourPort + "/Patient/1");
+		httpGet.addHeader(Constants.HEADER_CONTENT_TYPE, Constants.CT_FHIR_XML);
+
+		HttpResponse status = ourClient.execute(httpGet);
+		IOUtils.closeQuietly(status.getEntity().getContent());
+
+		ArgumentCaptor<String> captor = ArgumentCaptor.forClass(String.class);
+		verify(logger, times(1)).info(captor.capture());
+		assertEquals("read -  - Patient/1 - ", captor.getValue());
+	}
+
+	@Test
+	public void testRequestBodyCreate() throws Exception {
 
 		LoggingInterceptor interceptor = new LoggingInterceptor();
 		interceptor.setMessageFormat("${operationType} - ${operationName} - ${idOrResourceName} - ${requestBodyFhir}");
@@ -163,6 +206,33 @@ public class LoggingInterceptorDstu2Test {
 		assertEquals("create -  - Patient - <Patient xmlns=\"http://hl7.org/fhir\"><identifier><value value=\"VAL\"/></identifier></Patient>", captor.getValue());
 	}
 
+	@Test
+	public void testRequestBodyCreateException() 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);
+
+		ourThrowException = new NullPointerException("FOO");
+
+		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 {
 
@@ -348,7 +418,10 @@ public class LoggingInterceptorDstu2Test {
 		}
 
 		@Create
-		public MethodOutcome create(@ResourceParam Patient thePatient) {
+		public MethodOutcome create(@ResourceParam Patient thePatient) throws Exception {
+			if (ourThrowException != null) {
+				throw ourThrowException;
+			}
 			return new MethodOutcome(new IdDt("Patient/1"));
 		}
 

hapi-fhir-structures-dstu3/src/main/java/org/hl7/fhir/dstu3/hapi/validation/DefaultProfileValidationSupport.java

@@ -12,6 +12,7 @@ import java.util.Map;
 import java.util.Set;
 
 import org.apache.commons.io.Charsets;
+import org.apache.commons.lang3.Validate;
 import org.hl7.fhir.dstu3.model.Bundle;
 import org.hl7.fhir.dstu3.model.Bundle.BundleEntryComponent;
 import org.hl7.fhir.dstu3.model.CodeSystem;
@@ -89,6 +90,8 @@ public class DefaultProfileValidationSupport implements IValidationSupport {
 	@SuppressWarnings("unchecked")
 	@Override
 	public <T extends IBaseResource> T fetchResource(FhirContext theContext, Class<T> theClass, String theUri) {
+		Validate.notBlank(theUri, "theUri must not be null or blank");
+		
 		if (theUri.startsWith("http://hl7.org/fhir/StructureDefinition/")) {
 			return (T) fetchStructureDefinition(theContext, theUri);
 		}

hapi-fhir-structures-dstu3/src/main/java/org/hl7/fhir/dstu3/validation/InstanceValidator.java

@@ -1541,7 +1541,7 @@ public class InstanceValidator extends BaseValidator implements IResourceValidat
 
 	private void validateQuestionannaireResponse(List<ValidationMessage> errors, Element element, NodeStack stack) {
 		Element q = element.getNamedChild("questionnaire");
-		if (hint(errors, IssueType.REQUIRED, element.line(), element.col(), stack.getLiteralPath(), q != null, "No questionnaire is identified, so no validation can be performed against the base questionnaire")) {
+		if (hint(errors, IssueType.REQUIRED, element.line(), element.col(), stack.getLiteralPath(), q != null && isNotBlank(q.getNamedChildValue("reference")), "No questionnaire is identified, so no validation can be performed against the base questionnaire")) {
 			long t = System.nanoTime();
 			Questionnaire qsrc = context.fetchResource(Questionnaire.class, q.getNamedChildValue("reference"));
 			sdTime = sdTime + (System.nanoTime() - t);

hapi-fhir-structures-dstu3/src/test/java/ca/uhn/fhir/parser/XmlParserDstu3Test.java

@@ -120,14 +120,14 @@ public class XmlParserDstu3Test {
 	}
 
 	@Test
-	public void testEncodeContained() throws Exception {
+	public void testEncodeContainedWithNonLocalId() throws Exception {
 
 		Patient p = new Patient();
 		p.setId("Patient1");
 		p.setBirthDate(new SimpleDateFormat("yyyy-mm-dd HH:mm:ss").parse("2016-04-15 10:15:30"));
 
 		ProcedureRequest pr = new ProcedureRequest();
-		pr.setId("#1234567");
+		pr.setId("1234567");
 		pr.setSubject(new Reference(p));
 		pr.setCode(new CodeableConcept().addCoding(new Coding("breastfeeding-readiness-assessment", "Breastfeeding Readiness Assessment", "Breastfeeding Readiness Assessment")));
 //		pr.setReason(new StringType("Single Live Birth"));