Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue #2195 - Add additional logging #2604

Merged
merged 4 commits into from
Jul 13, 2021
Merged

Issue #2195 - Add additional logging #2604

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a7c6fe2
Issue #2195 - Add additional logging
tbieste Jul 12, 2021
fea0b61
Issue #2195 - Add GET method support to $retrieve-index
tbieste Jul 12, 2021
d6b7660
Issue #2195 - Update after review comments
tbieste Jul 12, 2021
14ff0e9
remove stale comment
lmsurpre Jul 13, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 15 additions & 2 deletions fhir-bucket/src/main/java/com/ibm/fhir/bucket/reindex/ClientDrivenReindexOperation.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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";

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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);
}
}
}
Expand All @@ -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();
Expand Down
21 changes: 14 additions & 7 deletions ...stence-jdbc/src/main/java/com/ibm/fhir/persistence/jdbc/impl/FHIRPersistenceJDBCImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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());
Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -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());
Expand All @@ -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);
Expand Down Expand Up @@ -2835,4 +2842,4 @@ public List<Long> retrieveIndex(int count, java.time.Instant notModifiedAfter, L
log.exiting(CLASSNAME, METHODNAME);
}
}
}
}
16 changes: 16 additions & 0 deletions ...ver-test/src/test/java/com/ibm/fhir/server/test/operation/RetrieveIndexOperationTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
7 changes: 4 additions & 3 deletions ...peration-reindex/src/main/java/com/ibm/fhir/operation/reindex/RetrieveIndexOperation.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
lmsurpre marked this conversation as resolved.
Show resolved Hide resolved
}

try {
Expand Down