Add some test debug logs

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java

@@ -593,6 +593,9 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 					shouldSync = true;
 				}
 
+				// If no abort was requested, bail out
+				Validate.isTrue(myAbortRequested == false, "Abort has been requested");
+
 				if (shouldSync) {
 					saveUnsynced(theResultIterator);
 				}
@@ -605,10 +608,11 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 					}
 				}
 
-				// Check if an abort got requested
+			}
+
+			// If no abort was requested, bail out
 			Validate.isTrue(myAbortRequested == false, "Abort has been requested");
 
-			}
 			saveUnsynced(theResultIterator);
 		}
 

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/config/TestDstu2Config.java

@@ -30,7 +30,7 @@ public class TestDstu2Config extends BaseJavaConfigDstu2 {
 	public DataSource dataSource() {
 		BasicDataSource retVal = new BasicDataSource();
 		retVal.setDriver(new org.apache.derby.jdbc.EmbeddedDriver());
-		retVal.setUrl("jdbc:derby:memory:myUnitTestDB;create=true");
+		retVal.setUrl("jdbc:derby:memory:myUnitTestDBDstu2;create=true");
 		retVal.setUsername("");
 		retVal.setPassword("");
 		return retVal;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/config/TestDstu3Config.java

@@ -90,7 +90,7 @@ public class TestDstu3Config extends BaseJavaConfigDstu3 {
 
 		};
 		retVal.setDriver(new org.apache.derby.jdbc.EmbeddedDriver());
-		retVal.setUrl("jdbc:derby:memory:myUnitTestDB;create=true");
+		retVal.setUrl("jdbc:derby:memory:myUnitTestDBDstu3;create=true");
 		retVal.setMaxWaitMillis(10000);
 		retVal.setUsername("");
 		retVal.setPassword("");

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/config/TestR4Config.java

@@ -85,7 +85,7 @@ public class TestR4Config extends BaseJavaConfigR4 {
 
 		};
 		retVal.setDriver(new org.apache.derby.jdbc.EmbeddedDriver());
-		retVal.setUrl("jdbc:derby:memory:myUnitTestDB;create=true");
+		retVal.setUrl("jdbc:derby:memory:myUnitTestDBR4;create=true");
 		retVal.setMaxWaitMillis(10000);
 		retVal.setUsername("");
 		retVal.setPassword("");

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

@@ -1,38 +1,12 @@
 package ca.uhn.fhir.jpa.dao;
 
-import static org.junit.Assert.fail;
-import static org.mockito.Mockito.mock;
-import static org.mockito.Mockito.when;
-
-import java.io.IOException;
-import java.io.InputStream;
-import java.sql.SQLException;
-import java.util.*;
-import java.util.concurrent.Callable;
-
-import javax.persistence.EntityManager;
-
-import ca.uhn.fhir.jpa.util.StopWatch;
-import ca.uhn.fhir.model.dstu2.resource.Observation;
-import org.apache.commons.io.IOUtils;
-import org.hibernate.search.jpa.Search;
-import org.hl7.fhir.dstu3.model.Bundle.BundleEntryComponent;
-import org.hl7.fhir.dstu3.model.Resource;
-import org.hl7.fhir.instance.model.api.*;
-import org.junit.AfterClass;
-import org.junit.Before;
-import org.mockito.Mockito;
-import org.springframework.transaction.PlatformTransactionManager;
-import org.springframework.transaction.TransactionStatus;
-import org.springframework.transaction.support.TransactionCallback;
-import org.springframework.transaction.support.TransactionTemplate;
-
 import ca.uhn.fhir.context.FhirContext;
 import ca.uhn.fhir.jpa.entity.*;
 import ca.uhn.fhir.jpa.provider.SystemProviderDstu2Test;
 import ca.uhn.fhir.jpa.search.ISearchCoordinatorSvc;
 import ca.uhn.fhir.jpa.sp.ISearchParamPresenceSvc;
 import ca.uhn.fhir.jpa.term.VersionIndependentConcept;
+import ca.uhn.fhir.jpa.util.StopWatch;
 import ca.uhn.fhir.model.dstu2.resource.Bundle;
 import ca.uhn.fhir.model.dstu2.resource.Bundle.Entry;
 import ca.uhn.fhir.rest.api.server.IBundleProvider;
@@ -41,6 +15,31 @@ import ca.uhn.fhir.rest.server.interceptor.IServerInterceptor;
 import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails;
 import ca.uhn.fhir.util.BundleUtil;
 import ca.uhn.fhir.util.TestUtil;
+import org.apache.commons.io.IOUtils;
+import org.hibernate.search.jpa.Search;
+import org.hl7.fhir.dstu3.model.Bundle.BundleEntryComponent;
+import org.hl7.fhir.dstu3.model.Resource;
+import org.hl7.fhir.instance.model.api.IBaseBundle;
+import org.hl7.fhir.instance.model.api.IBaseResource;
+import org.hl7.fhir.instance.model.api.IIdType;
+import org.junit.AfterClass;
+import org.junit.Before;
+import org.mockito.Mockito;
+import org.springframework.transaction.PlatformTransactionManager;
+import org.springframework.transaction.TransactionStatus;
+import org.springframework.transaction.support.TransactionCallback;
+import org.springframework.transaction.support.TransactionTemplate;
+
+import javax.persistence.EntityManager;
+import java.io.IOException;
+import java.io.InputStream;
+import java.sql.SQLException;
+import java.util.*;
+import java.util.concurrent.Callable;
+
+import static org.junit.Assert.*;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
 
 public abstract class BaseJpaTest {
 
@@ -53,13 +52,23 @@ public abstract class BaseJpaTest {
 	public void beforeCreateSrd() {
 		mySrd = mock(ServletRequestDetails.class, Mockito.RETURNS_DEEP_STUBS);
 		when(mySrd.getRequestOperationCallback()).thenReturn(myRequestOperationCallback);
-		myServerInterceptorList = new ArrayList<IServerInterceptor>();
+		myServerInterceptorList = new ArrayList<>();
 		when(mySrd.getServer().getInterceptors()).thenReturn(myServerInterceptorList);
-		when(mySrd.getUserData()).thenReturn(new HashMap<Object, Object>());
+		when(mySrd.getUserData()).thenReturn(new HashMap<>());
 	}
 
 	protected abstract FhirContext getContext();
 
+	/**
+	 * Sleep until at least 1 ms has elapsed
+	 */
+	public void sleepUntilTimeChanges() throws InterruptedException {
+		StopWatch sw = new StopWatch();
+		while (sw.getMillis() == 0) {
+			Thread.sleep(10);
+		}
+	}
+
 	protected org.hl7.fhir.dstu3.model.Bundle toBundle(IBundleProvider theSearch) {
 		org.hl7.fhir.dstu3.model.Bundle bundle = new org.hl7.fhir.dstu3.model.Bundle();
 		for (IBaseResource next : theSearch.getResources(0, theSearch.size())) {
@@ -76,7 +85,7 @@ public abstract class BaseJpaTest {
 		return bundle;
 	}
 
-	@SuppressWarnings({ "rawtypes" })
+	@SuppressWarnings({"rawtypes"})
 	protected List toList(IBundleProvider theSearch) {
 		return theSearch.getResources(0, theSearch.size());
 	}

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu2/FhirResourceDaoDstu2Test.java

@@ -2346,7 +2346,7 @@ public class FhirResourceDaoDstu2Test extends BaseJpaDstu2Test {
 	}
 
 	@Test
-	public void testSortByLastUpdated() {
+	public void testSortByLastUpdated() throws InterruptedException {
 		String methodName = "testSortByLastUpdated";
 
 		Patient p = new Patient();
@@ -2354,21 +2354,29 @@ public class FhirResourceDaoDstu2Test extends BaseJpaDstu2Test {
 		p.addName().addFamily(methodName);
 		IIdType id1 = myPatientDao.create(p, mySrd).getId().toUnqualifiedVersionless();
 
+		sleepUntilTimeChanges();
+
 		p = new Patient();
 		p.addIdentifier().setSystem("urn:system2").setValue(methodName);
 		p.addName().addFamily(methodName);
 		IIdType id2 = myPatientDao.create(p, mySrd).getId().toUnqualifiedVersionless();
 
+		sleepUntilTimeChanges();
+
 		p = new Patient();
 		p.addIdentifier().setSystem("urn:system3").setValue(methodName);
 		p.addName().addFamily(methodName);
 		IIdType id3 = myPatientDao.create(p, mySrd).getId().toUnqualifiedVersionless();
 
+		sleepUntilTimeChanges();
+
 		p = new Patient();
 		p.addIdentifier().setSystem("urn:system4").setValue(methodName);
 		p.addName().addFamily(methodName);
 		IIdType id4 = myPatientDao.create(p, mySrd).getId().toUnqualifiedVersionless();
 
+		sleepUntilTimeChanges();
+
 		SearchParameterMap pm;
 		List<IIdType> actual;
 

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

@@ -1,14 +1,17 @@
 package ca.uhn.fhir.jpa.dao.dstu3;
 
-import static ca.uhn.fhir.jpa.util.TestUtil.sleepAtLeast;
+import ca.uhn.fhir.jpa.dao.SearchParameterMap;
-import static org.hamcrest.Matchers.containsInAnyOrder;
+import ca.uhn.fhir.jpa.entity.Search;
-import static org.junit.Assert.*;
+import ca.uhn.fhir.jpa.search.StaleSearchDeletingSvcImpl;
-
 import ca.uhn.fhir.jpa.util.StopWatch;
+import ca.uhn.fhir.rest.api.server.IBundleProvider;
+import ca.uhn.fhir.rest.param.StringParam;
 import org.apache.commons.lang3.Validate;
 import org.hl7.fhir.dstu3.model.Patient;
 import org.hl7.fhir.instance.model.api.IIdType;
-import org.junit.*;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.springframework.test.util.AopTestUtils;
@@ -16,10 +19,11 @@ import org.springframework.transaction.TransactionStatus;
 import org.springframework.transaction.support.TransactionCallbackWithoutResult;
 import org.springframework.transaction.support.TransactionTemplate;
 
-import ca.uhn.fhir.jpa.dao.SearchParameterMap;
+import java.util.concurrent.atomic.AtomicLong;
-import ca.uhn.fhir.jpa.search.StaleSearchDeletingSvcImpl;
+
-import ca.uhn.fhir.rest.api.server.IBundleProvider;
+import static ca.uhn.fhir.jpa.util.TestUtil.sleepAtLeast;
-import ca.uhn.fhir.rest.param.StringParam;
+import static org.hamcrest.Matchers.containsInAnyOrder;
+import static org.junit.Assert.*;
 
 public class FhirResourceDaoDstu3SearchPageExpiryTest extends BaseJpaDstu3Test {
 	private static final Logger ourLog = LoggerFactory.getLogger(FhirResourceDaoDstu3SearchPageExpiryTest.class);
@@ -104,14 +108,17 @@ public class FhirResourceDaoDstu3SearchPageExpiryTest extends BaseJpaDstu3Test {
 		// Search just got used so it shouldn't be deleted
 
 		myStaleSearchDeletingSvc.pollForStaleSearchesAndDeleteThem();
+		final AtomicLong search3timestamp = new AtomicLong();
 		newTxTemplate().execute(new TransactionCallbackWithoutResult() {
 			@Override
 			protected void doInTransactionWithoutResult(TransactionStatus theArg0) {
-				assertNotNull(mySearchEntityDao.findByUuid(searchUuid3));
+				Search search3 = mySearchEntityDao.findByUuid(searchUuid3);
+				assertNotNull(search3);
+				search3timestamp.set(search3.getCreated().getTime());
 			}
 		});
 
-		StaleSearchDeletingSvcImpl.setNowForUnitTests(start + 1400);
+		StaleSearchDeletingSvcImpl.setNowForUnitTests(search3timestamp.get() + 1400);
 
 		myStaleSearchDeletingSvc.pollForStaleSearchesAndDeleteThem();
 		newTxTemplate().execute(new TransactionCallbackWithoutResult() {
@@ -127,14 +134,14 @@ public class FhirResourceDaoDstu3SearchPageExpiryTest extends BaseJpaDstu3Test {
 			}
 		});
 
-		StaleSearchDeletingSvcImpl.setNowForUnitTests(start + 2200);
+		StaleSearchDeletingSvcImpl.setNowForUnitTests(search3timestamp.get() + 2200);
 
 		myStaleSearchDeletingSvc.pollForStaleSearchesAndDeleteThem();
 		newTxTemplate().execute(new TransactionCallbackWithoutResult() {
 			@Override
 			protected void doInTransactionWithoutResult(TransactionStatus theArg0) {
-				assertNull(mySearchEntityDao.findByUuid(searchUuid1));
+				assertNull("Search 1 still exists", mySearchEntityDao.findByUuid(searchUuid1));
-				assertNull(mySearchEntityDao.findByUuid(searchUuid3));
+				assertNull("Search 3 still exists", mySearchEntityDao.findByUuid(searchUuid3));
 			}
 		});