Issue #2195 - Add additional logging (#2604)

Signed-off-by: Lee Surprenant <lmsurpre@us.ibm.com>
LinuxForHealth · Jul 13, 2021 · 4372606 · 4372606
1 parent 57b399c
commit 4372606
Show file tree

Hide file tree

Showing 4 changed files with 49 additions and 12 deletions.
diff --git a/fhir-bucket/src/main/java/com/ibm/fhir/bucket/reindex/ClientDrivenReindexOperation.java b/fhir-bucket/src/main/java/com/ibm/fhir/bucket/reindex/ClientDrivenReindexOperation.java
@@ -47,6 +47,7 @@ public class ClientDrivenReindexOperation extends DriveReindexOperation {
     private static final int OFFER_TIMEOUT_IN_SEC = 30;
     private static final int POLL_TIMEOUT_IN_SEC = 5;
     private static final int MAX_RESTARTS = 10;
+    private static final int MAX_WAIT_TO_FINISH = 60;
     private static final String RETRIEVE_INDEX_URL = "$retrieve-index";
     private static final String REINDEX_URL = "$reindex";
 
@@ -170,7 +171,7 @@ public void monitorLoop() {
                     // See if we can make one successful request before filling the pool
                     // with hundreds of parallel requests
                     int currentThreadCount = this.currentlyRunning.get();
-                    if (currentThreadCount == 0) {
+                    if (currentThreadCount < 1) {
                         // Before starting, ensure the last index IDs is reset so index IDs that were in progress are not skipped
                         resetProgress();
                         // Add limit to number of times this will attempt to restart due to errors
@@ -208,7 +209,7 @@ public void monitorLoop() {
                                     this.running = false;
                                 } else {
                                     // Worker threads are still processing, so sleep for a bit before we check again
-                                    safeSleep(1000);
+                                    safeSleep(5000);
                                 }
                             }
                         }
@@ -226,6 +227,18 @@ public void monitorLoop() {
                 }
             }
         } finally {
+            // Wait for worker threads to end
+            int waitCount = 0;
+            while (waitCount++ < MAX_WAIT_TO_FINISH) {
+                int currentThreadCount = this.currentlyRunning.get();
+                if (currentThreadCount < 1) {
+                    break;
+                }
+                // Worker threads are still running, so sleep for a bit before we check again
+                logger.info("Waiting for " + currentThreadCount + " threads to complete before exiting");
+                safeSleep(5000);
+            }
+
             // Check if there is any reindexing work left to do, and log an appropriate message based on the situation
             if (!doneRetrieving || !inProgressIndexIds.isEmpty()) {
                 String lastIndexIdProcessed = getLastIndexIdProcessed();

diff --git a/...stence-jdbc/src/main/java/com/ibm/fhir/persistence/jdbc/impl/FHIRPersistenceJDBCImpl.java b/...stence-jdbc/src/main/java/com/ibm/fhir/persistence/jdbc/impl/FHIRPersistenceJDBCImpl.java
@@ -2503,6 +2503,7 @@ public int reindex(FHIRPersistenceContext context, OperationOutcome.Builder oper
         log.entering(CLASSNAME, METHODNAME);
 
         int result = 0;
+        ResourceIndexRecord rir = null;
 
         if (log.isLoggable(Level.FINE)) {
             log.fine("reindex tstamp=" + tstamp.toString());
@@ -2514,6 +2515,10 @@ public int reindex(FHIRPersistenceContext context, OperationOutcome.Builder oper
             throw new FHIRPersistenceException("Reindex tstamp cannot be in the future");
         }
 
+        if (indexIds != null) {
+            log.info("Reindex requested for index IDs " + indexIds);
+        }
+
         try (Connection connection = openConnection()) {
             ResourceDAO resourceDao = makeResourceDAO(connection);
             ParameterDAO parameterDao = makeParameterDAO(connection);
@@ -2542,7 +2547,6 @@ public int reindex(FHIRPersistenceContext context, OperationOutcome.Builder oper
 
             // If list of indexIds was specified, loop over those. Otherwise, since we skip over
             // deleted resources we have to loop until we find something not deleted, or reach the end.
-            ResourceIndexRecord rir;
             do {
                 long start = System.nanoTime();
                 rir = reindexDAO.getResourceToReindex(tstamp, indexIds != null ? indexIds.get(indexIdsProcessed++) : null, resourceTypeId, logicalId);
@@ -2555,8 +2559,9 @@ public int reindex(FHIRPersistenceContext context, OperationOutcome.Builder oper
 
                 if (rir != null) {
 
-                    // This is important so we log it as info
-                    log.info("Reindexing FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'");
+                    if (log.isLoggable(Level.FINE)) {
+                        log.fine("Reindexing FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'");
+                    }
 
                     // Read the current resource
                     com.ibm.fhir.persistence.jdbc.dto.Resource existingResourceDTO = resourceDao.read(rir.getLogicalId(), rir.getResourceType());
@@ -2581,28 +2586,30 @@ public int reindex(FHIRPersistenceContext context, OperationOutcome.Builder oper
 
         } catch(FHIRPersistenceFKVException e) {
             getTransaction().setRollbackOnly();
+            log.log(Level.SEVERE, "Unexpected error while performing reindex" + (rir != null ? (" of FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'") : ""), e);
             throw e;
         } catch(FHIRPersistenceException e) {
             getTransaction().setRollbackOnly();
+            log.log(Level.SEVERE, "Unexpected error while performing reindex" + (rir != null ? (" of FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'") : ""), e);
             throw e;
         } catch (DataAccessException dax) {
             getTransaction().setRollbackOnly();
 
             // It's possible this is a deadlock exception, in which case it could be considered retryable
             if (dax.isTransactionRetryable()) {
-                log.log(Level.WARNING, "retryable error", dax);
+                log.log(Level.WARNING, "Retryable error while performing reindex" + (rir != null ? (" of FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'") : ""), dax);
                 FHIRPersistenceDataAccessException fpx = new FHIRPersistenceDataAccessException("Data access error while performing a reindex operation.");
                 fpx.setTransactionRetryable(true);
                 throw fpx;
             } else {
-                log.log(Level.SEVERE, "non-retryable error", dax);
+                log.log(Level.SEVERE, "Non-retryable error while performing reindex" + (rir != null ? (" of FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'") : ""), dax);
                 throw new FHIRPersistenceDataAccessException("Data access error while performing a reindex operation.");
             }
         } catch(Throwable e) {
             getTransaction().setRollbackOnly();
+            log.log(Level.SEVERE, "Unexpected error while performing a reindex" + (rir != null ? (" of FHIR Resource '" + rir.getResourceType() + "/" + rir.getLogicalId() + "'") : ""), e);
             // don't chain the exception to avoid leaking secrets
             FHIRPersistenceException fx = new FHIRPersistenceException("Unexpected error while performing a reindex operation.");
-            log.log(Level.SEVERE, fx.getMessage(), e);
             throw fx;
         } finally {
             log.exiting(CLASSNAME, METHODNAME);
@@ -2835,4 +2842,4 @@ public List<Long> retrieveIndex(int count, java.time.Instant notModifiedAfter, L
             log.exiting(CLASSNAME, METHODNAME);
         }
     }
-}
+}
diff --git a/...ver-test/src/test/java/com/ibm/fhir/server/test/operation/RetrieveIndexOperationTest.java b/...ver-test/src/test/java/com/ibm/fhir/server/test/operation/RetrieveIndexOperationTest.java
@@ -69,6 +69,22 @@ public void testRetrieveIndex() {
         assertEquals(r.getStatus(), Status.OK.getStatusCode());
     }
 
+    @Test
+    public void testRetrieveIndex_GET() {
+        WebTarget target = getWebTarget();
+        target = target.path("/$retrieve-index")
+                .queryParam("_count", "5")
+                .queryParam("notModifiedAfter", Instant.now().toString())
+                .queryParam("afterIndexId", "8");
+
+        Response r = target.request(FHIRMediaType.APPLICATION_FHIR_JSON)
+                .header("X-FHIR-TENANT-ID", "default")
+                .header("X-FHIR-DSID", "default")
+                .get();
+
+        assertEquals(r.getStatus(), Status.OK.getStatusCode());
+    }
+
     @Test
     public void testRetrieveIndex_type() {
         WebTarget target = getWebTarget();

diff --git a/...peration-reindex/src/main/java/com/ibm/fhir/operation/reindex/RetrieveIndexOperation.java b/...peration-reindex/src/main/java/com/ibm/fhir/operation/reindex/RetrieveIndexOperation.java
@@ -25,6 +25,7 @@
 import com.ibm.fhir.model.resource.OperationDefinition;
 import com.ibm.fhir.model.resource.Parameters;
 import com.ibm.fhir.model.resource.Resource;
+import com.ibm.fhir.model.type.code.IssueType;
 import com.ibm.fhir.server.operation.spi.AbstractOperation;
 import com.ibm.fhir.server.operation.spi.FHIROperationContext;
 import com.ibm.fhir.server.operation.spi.FHIRResourceHelpers;
@@ -73,10 +74,10 @@ protected Parameters doInvoke(FHIROperationContext operationContext, Class<? ext
             String logicalId, String versionId, Parameters parameters, FHIRResourceHelpers resourceHelper)
             throws FHIROperationException {
 
-        // Only POST is allowed
+        // Only GET or POST is allowed
         String method = (String) operationContext.getProperty(FHIROperationContext.PROPNAME_METHOD_TYPE);
-        if (!"POST".equalsIgnoreCase(method)) {
-            throw new FHIROperationException("HTTP method not supported: " + method);
+        if (!"GET".equalsIgnoreCase(method) && !"POST".equalsIgnoreCase(method)) {
+            throw FHIROperationUtil.buildExceptionWithIssue("HTTP method not supported: " + method, IssueType.NOT_SUPPORTED);
         }
 
         try {