diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/SolrInformationServer.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/SolrInformationServer.java index 4ca525913..c59e1d2ea 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/SolrInformationServer.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/SolrInformationServer.java @@ -3090,7 +3090,8 @@ public class SolrInformationServer implements InformationServer { if (!activeTrackerThreads.contains(Thread.currentThread().getId())) { - throw new TrackerStateException("The trackers work was rolled back by another tracker error"); + throw new TrackerStateException( + "The trackers work was rolled back by another tracker error. The original cause has been dumped previously in the log."); } } finally diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractTracker.java index f4d381cd1..47930d6c0 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractTracker.java @@ -68,6 +68,10 @@ public abstract class AbstractTracker implements Tracker protected boolean transformContent; String shardTemplate; protected volatile boolean rollback; + /** + * When rollback is set, original error is also gathered in order to provide detailed logging. + */ + protected Throwable rollbackCausedBy; protected final Type type; /* @@ -176,13 +180,13 @@ public abstract class AbstractTracker implements Tracker assert(assertTrackerStateRemainsNull()); } - LOGGER.info("... Running {} for core [{}]", this.getClass().getSimpleName(), coreName); + LOGGER.info("[CORE {}] Running {}", coreName, this.getClass().getSimpleName()); if(this.state == null) { this.state = getTrackerState(); - LOGGER.debug("Global Tracker State set to: {}", this.state.toString()); + LOGGER.debug("[CORE {}] Global Tracker State set to: {}", coreName, this.state.toString()); this.state.setRunning(true); } else @@ -199,34 +203,29 @@ public abstract class AbstractTracker implements Tracker } catch(IndexTrackingShutdownException t) { - setRollback(true); - LOGGER.info("Stopping index tracking for {} - {}", getClass().getSimpleName(), coreName); + setRollback(true, t); + LOGGER.info("[CORE {}] Stopping index tracking for {}", coreName, getClass().getSimpleName()); } catch(Throwable t) { - setRollback(true); + setRollback(true, t); if (t instanceof SocketTimeoutException || t instanceof ConnectException) { + LOGGER.warn("[CORE {}] Tracking communication timed out for {}", coreName, getClass().getSimpleName()); if (LOGGER.isDebugEnabled()) { - // DEBUG, so give the whole stack trace - LOGGER.warn("Tracking communication timed out for {} - {}", getClass().getSimpleName(), coreName, t); - } - else - { - // We don't need the stack trace. It timed out. - LOGGER.warn("Tracking communication timed out for for {} - {}", getClass().getSimpleName(), coreName); + LOGGER.debug("[CORE {}] Stack trace", coreName, t); } } else { - LOGGER.error("Tracking failed for for {} - {}", getClass().getSimpleName(), coreName, t); + LOGGER.error("[CORE {}] Tracking failed for {}", coreName, getClass().getSimpleName(), t); } } } catch (InterruptedException e) { - LOGGER.error("Semaphore interrupted for for {} - {}", getClass().getSimpleName(), coreName, e); + LOGGER.error("[CORE {}] Semaphore interrupted for {}", coreName, getClass().getSimpleName(), e); } finally { @@ -244,10 +243,16 @@ public abstract class AbstractTracker implements Tracker { return this.rollback; } + + public Throwable getRollbackCausedBy() + { + return this.rollbackCausedBy; + } - public void setRollback(boolean rollback) + public void setRollback(boolean rollback, Throwable rollbackCausedBy) { this.rollback = rollback; + this.rollbackCausedBy = rollbackCausedBy; } private void continueState() diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractWorkerRunnable.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractWorkerRunnable.java index 30f228ebe..2aa335d98 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractWorkerRunnable.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractWorkerRunnable.java @@ -40,6 +40,7 @@ abstract class AbstractWorkerRunnable implements Runnable public void run() { boolean failed = true; + Exception failCausedBy = null; try { doWork(); @@ -47,7 +48,8 @@ abstract class AbstractWorkerRunnable implements Runnable } catch (Exception e) { - log.warn("Index tracking batch hit an unrecoverable error ", e); + log.warn("Index tracking batch hit an unrecoverable error ", e); + failCausedBy = e; } finally { @@ -55,12 +57,12 @@ abstract class AbstractWorkerRunnable implements Runnable queueHandler.removeFromQueueAndProdHead(this); if(failed) { - onFail(); + onFail(failCausedBy); } } } abstract protected void doWork() throws Exception; - abstract protected void onFail(); + abstract protected void onFail(Throwable failCausedBy); } diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AclTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AclTracker.java index 3092c7d1b..e28785c7a 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AclTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AclTracker.java @@ -54,7 +54,7 @@ import org.slf4j.LoggerFactory; public class AclTracker extends AbstractTracker { - protected final static Logger log = LoggerFactory.getLogger(AclTracker.class); + protected final static Logger LOGGER = LoggerFactory.getLogger(AclTracker.class); private static final int DEFAULT_CHANGE_SET_ACLS_BATCH_SIZE = 100; private static final int DEFAULT_ACL_BATCH_SIZE = 10; @@ -135,12 +135,14 @@ public class AclTracker extends AbstractTracker indexAcl(readers, false); } this.infoSrv.indexAclTransaction(changeSet, false); - log.info("INDEX ACTION - AclChangeSetId {} has been indexed", aclChangeSetId); + LOGGER.info("[CORE {}] - INDEX ACTION - AclChangeSetId {} has been indexed", coreName, aclChangeSetId); requiresCommit = true; } else { - log.info("INDEX ACTION - AclChangeSetId {} was not found in database, it has NOT been reindexed", aclChangeSetId); + LOGGER.info( + "[CORE {}] - INDEX ACTION - AclChangeSetId {} was not found in database, it has NOT been reindexed", + coreName, aclChangeSetId); } } checkShutdown(); @@ -165,7 +167,7 @@ public class AclTracker extends AbstractTracker //AclReaders r = readers.get(0); //System.out.println("############## READERS ID:"+r.getId()+":"+r.getReaders()); indexAcl(readers, false); - log.info("INDEX ACTION - AclId {} has been indexed", aclId); + LOGGER.info("[CORE {}] - INDEX ACTION - AclId {} has been indexed", coreName, aclId); } checkShutdown(); } @@ -193,12 +195,14 @@ public class AclTracker extends AbstractTracker } this.infoSrv.indexAclTransaction(changeSet, true); - log.info("REINDEX ACTION - AclChangeSetId {} has been reindexed", aclChangeSetId); + LOGGER.info("[CORE {}] - REINDEX ACTION - AclChangeSetId {} has been reindexed", coreName, aclChangeSetId); requiresCommit = true; } else { - log.info("REINDEX ACTION - AclChangeSetId {} was not found in database, it has NOT been reindexed", aclChangeSetId); + LOGGER.info( + "[CORE {}] - REINDEX ACTION - AclChangeSetId {} was not found in database, it has NOT been reindexed", + coreName, aclChangeSetId); } } checkShutdown(); @@ -223,7 +227,7 @@ public class AclTracker extends AbstractTracker Acl acl = new Acl(0, aclId); List readers = client.getAclReaders(Collections.singletonList(acl)); indexAcl(readers, true); - log.info("REINDEX ACTION - aclId {} has been reindexed", aclId); + LOGGER.info("[CORE {}] - REINDEX ACTION - aclId {} has been reindexed", coreName, aclId); requiresCommit = true; } checkShutdown(); @@ -243,7 +247,7 @@ public class AclTracker extends AbstractTracker if (aclChangeSetId != null) { this.infoSrv.deleteByAclChangeSetId(aclChangeSetId); - log.info("PURGE ACTION - Purged aclChangeSetId {}", aclChangeSetId); + LOGGER.info("[CORE {}] - PURGE ACTION - Purged aclChangeSetId {}", coreName, aclChangeSetId); } checkShutdown(); } @@ -258,7 +262,7 @@ public class AclTracker extends AbstractTracker if (aclId != null) { this.infoSrv.deleteByAclId(aclId); - log.info("PURGE ACTION - Purged aclId {}", aclId); + LOGGER.info("[CORE {}] - PURGE ACTION - Purged aclId {}", coreName, aclId); } checkShutdown(); } @@ -330,7 +334,7 @@ public class AclTracker extends AbstractTracker { state.setCheckedLastAclTransactionTime(true); state.setCheckedFirstAclTransactionTime(true); - log.info("No acl transactions found - no verification required"); + LOGGER.info("[CORE {}] - No acl transactions found - no verification required", coreName); firstChangeSets = client.getAclChangeSets(null, 0L, null, 2000L, 1); if (!firstChangeSets.getAclChangeSets().isEmpty()) @@ -354,20 +358,20 @@ public class AclTracker extends AbstractTracker if (setSize == 0) { - log.error("First acl transaction was not found with the correct timestamp."); - log.error("SOLR has successfully connected to your repository however the SOLR indexes and repository database do not match."); - log.error("If this is a new or rebuilt database your SOLR indexes also need to be re-built to match the database."); - log.error("You can also check your SOLR connection details in solrcore.properties."); + LOGGER.error("[CORE {}] First acl transaction was not found with the correct timestamp.", coreName); + LOGGER.error("SOLR has successfully connected to your repository however the SOLR indexes and repository database do not match."); + LOGGER.error("If this is a new or rebuilt database your SOLR indexes also need to be re-built to match the database."); + LOGGER.error("You can also check your SOLR connection details in solrcore.properties."); throw new AlfrescoRuntimeException("Initial acl transaction not found with correct timestamp"); } else if (setSize == 1) { state.setCheckedFirstTransactionTime(true); - log.info("Verified first acl transaction and timestamp in index"); + LOGGER.info("[CORE {}] Verified first acl transaction and timestamp in index", coreName); } else { - log.warn("Duplicate initial acl transaction found with correct timestamp"); + LOGGER.warn("[CORE {}] Duplicate initial acl transaction found with correct timestamp", coreName); } } } @@ -388,19 +392,19 @@ public class AclTracker extends AbstractTracker AclChangeSet maxAclTxInIndex = this.infoSrv.getMaxAclChangeSetIdAndCommitTimeInIndex(); if (maxAclTxInIndex.getCommitTimeMs() > maxChangeSetCommitTimeInRepo) { - log.error("Last acl transaction was found in index with timestamp later than that of repository."); - log.error("Max Acl Tx In Index: " + maxAclTxInIndex.getId() + ", In Repo: " + maxChangeSetIdInRepo); - log.error("Max Acl Tx Commit Time In Index: " + maxAclTxInIndex.getCommitTimeMs() + ", In Repo: " + LOGGER.error("[CORE {}] Last acl transaction was found in index with timestamp later than that of repository.", coreName); + LOGGER.error("Max Acl Tx In Index: " + maxAclTxInIndex.getId() + ", In Repo: " + maxChangeSetIdInRepo); + LOGGER.error("Max Acl Tx Commit Time In Index: " + maxAclTxInIndex.getCommitTimeMs() + ", In Repo: " + maxChangeSetCommitTimeInRepo); - log.error("SOLR has successfully connected to your repository however the SOLR indexes and repository database do not match."); - log.error("If this is a new or rebuilt database your SOLR indexes also need to be re-built to match the database."); - log.error("You can also check your SOLR connection details in solrcore.properties."); + LOGGER.error("SOLR has successfully connected to your repository however the SOLR indexes and repository database do not match."); + LOGGER.error("If this is a new or rebuilt database your SOLR indexes also need to be re-built to match the database."); + LOGGER.error("You can also check your SOLR connection details in solrcore.properties."); throw new AlfrescoRuntimeException("Last acl transaction found in index with incorrect timestamp"); } else { state.setCheckedLastAclTransactionTime(true); - log.info("Verified last acl transaction timestamp in index less than or equal to that of repository."); + LOGGER.info("[CORE {}] - Verified last acl transaction timestamp in index less than or equal to that of repository.", coreName); } } } @@ -430,7 +434,7 @@ public class AclTracker extends AbstractTracker AclChangeSets aclChangeSets; // step forward in time until we find something or hit the time bound // max id unbounded - Long startTime = fromCommitTime == null ? Long.valueOf(0L) :fromCommitTime; + Long startTime = fromCommitTime == null ? Long.valueOf(0L) : fromCommitTime; do { aclChangeSets = client.getAclChangeSets(startTime, null, startTime + actualTimeStep, null, maxResults); @@ -659,30 +663,58 @@ public class AclTracker extends AbstractTracker */ this.state = getTrackerState(); - + Long fromCommitTime = getChangeSetFromCommitTime(changeSetsFound, state.getLastGoodChangeSetCommitTimeInIndex()); aclChangeSets = getSomeAclChangeSets(changeSetsFound, fromCommitTime, TIME_STEP_1_HR_IN_MS, 2000, state.getTimeToStopIndexing()); - - + setLastChangeSetIdAndCommitTimeInTrackerState(aclChangeSets, state); - log.info("Scanning Acl change sets ..."); - if (aclChangeSets.getAclChangeSets().size() > 0) { - log.info(".... from " + aclChangeSets.getAclChangeSets().get(0)); - log.info(".... to " + aclChangeSets.getAclChangeSets().get(aclChangeSets.getAclChangeSets().size() - 1)); - } else { - log.info(".... none found after lastTxCommitTime " + fromCommitTime); + if (aclChangeSets.getAclChangeSets().size() > 0) + { + LOGGER.info("{}-[CORE {}] Found {} ACL change sets after lastTxCommitTime {}, ACL Change Sets from {} to {}", + Thread.currentThread().getId(), + coreName, + aclChangeSets.getAclChangeSets().size(), + fromCommitTime, + aclChangeSets.getAclChangeSets().get(0), + aclChangeSets.getAclChangeSets().get(aclChangeSets.getAclChangeSets().size() - 1)); + } + else + { + LOGGER.info("{}-[CORE {}] No ACL change set found after lastTxCommitTime {}", + Thread.currentThread().getId(), coreName, fromCommitTime); } - + ArrayList changeSetBatch = new ArrayList(); - for (AclChangeSet changeSet : aclChangeSets.getAclChangeSets()) { + for (int i = 0; i < aclChangeSets.getAclChangeSets().size(); i++) + { + + AclChangeSet changeSet = aclChangeSets.getAclChangeSets().get(i); + boolean isInIndex = (changeSet.getCommitTimeMs() <= state.getLastIndexedChangeSetCommitTime() && infoSrv.aclChangeSetInIndex(changeSet.getId(), true)); - - if (isInIndex) { + + if (isInIndex) + { + // Logging progress for large ACL Change Set tracking every 100 tracked ACLs + if (LOGGER.isTraceEnabled()) + { + LOGGER.trace("{}-[CORE {}] Tracking {} of {} ACL Change Sets. Change Set Id was already indexed: {}", + Thread.currentThread().getId(), coreName, i + 1, aclChangeSets.getAclChangeSets().size(), changeSet.getId()); + } changeSetsFound.add(changeSet); - } else { + } + else + { + + // Logging progress for ACL Change Set + if (LOGGER.isTraceEnabled()) + { + LOGGER.trace("{}-[CORE {}] Tracking {} of {} ACL Change Sets. Current Change Set Id to be indexed: {}", + Thread.currentThread().getId(), coreName, i + 1, aclChangeSets.getAclChangeSets().size(), changeSet.getId()); + } + // Make sure we do not go ahead of where we started - we will check the holes here // correctly next time if (changeSet.getCommitTimeMs() > state.getTimeToStopIndexing()) { @@ -745,10 +777,12 @@ public class AclTracker extends AbstractTracker { getWriteLock().release(); } + } while ((aclChangeSets.getAclChangeSets().size() > 0) && (upToDate == false)); + + LOGGER.info("{}-[CORE {}] Tracked {} ACLs", Thread.currentThread().getId(), coreName, totalAclCount); - log.info("total number of acls updated: " + totalAclCount); } private void setLastChangeSetIdAndCommitTimeInTrackerState(AclChangeSets aclChangeSets, TrackerState state) @@ -811,12 +845,19 @@ public class AclTracker extends AbstractTracker ArrayList aclBatch = new ArrayList(); List acls = client.getAcls(nonEmptyChangeSets, null, Integer.MAX_VALUE); + + if (LOGGER.isDebugEnabled()) + { + LOGGER.debug("{}-[CORE {}] Found {} Acls from Acl Change Sets: {}", Thread.currentThread().getId(), + coreName, acls.size(), nonEmptyChangeSets); + } for (Acl acl : acls) { - if (log.isDebugEnabled()) + if (LOGGER.isTraceEnabled()) { - log.debug(acl.toString()); + LOGGER.trace("{}-[CORE {}] Adding ACL {} to scheduled indexing job", Thread.currentThread().getId(), + coreName, acl.toString()); } aclBatch.add(acl); if (aclBatch.size() > aclBatchSize) @@ -859,9 +900,9 @@ public class AclTracker extends AbstractTracker } @Override - protected void onFail() + protected void onFail(Throwable failCausedBy) { - setRollback(true); + setRollback(true, failCausedBy); } private List filterAcls(List acls) diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CascadeTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CascadeTracker.java index 56f0f6b3f..18e79394f 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CascadeTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CascadeTracker.java @@ -114,9 +114,9 @@ public class CascadeTracker extends AbstractTracker implements Tracker } @Override - protected void onFail() + protected void onFail(Throwable failCausedBy) { - setRollback(true); + setRollback(true, failCausedBy); } } diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CommitTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CommitTracker.java index 6f7332035..e087752b2 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CommitTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CommitTracker.java @@ -194,6 +194,17 @@ public class CommitTracker extends AbstractTracker } infoSrv.rollback(); + + // Log reasons why the rollback is performed + if (aclTracker.getRollbackCausedBy() != null) + { + log.warn("Rollback performed due to ACL Tracker error", aclTracker.getRollbackCausedBy()); + } + if (metadataTracker.getRollbackCausedBy() != null) + { + log.warn("Rollback performed due to Metadata Tracker error", metadataTracker.getRollbackCausedBy()); + } + } catch (Exception e) { @@ -202,19 +213,19 @@ public class CommitTracker extends AbstractTracker finally { //Reset acl Tracker - aclTracker.setRollback(false); + aclTracker.setRollback(false, null); aclTracker.invalidateState(); //Reset metadataTracker - metadataTracker.setRollback(false); + metadataTracker.setRollback(false, null); metadataTracker.invalidateState(); //Reset contentTracker - contentTracker.setRollback(false); + contentTracker.setRollback(false, null); contentTracker.invalidateState(); //Reset cascadeTracker - cascadeTracker.ifPresent(c -> c.setRollback(false)); + cascadeTracker.ifPresent(c -> c.setRollback(false, null)); cascadeTracker.ifPresent(c -> invalidateState()); //Release the locks diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ContentTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ContentTracker.java index 4c3ed15a8..e4b837280 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ContentTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ContentTracker.java @@ -155,9 +155,10 @@ public class ContentTracker extends AbstractTracker implements Tracker } @Override - protected void onFail() + protected void onFail(Throwable failCausedBy) { - // Will redo if not persisted + // This will be redone in future tracking operations + log.warn("Content tracker failed due to {}", failCausedBy.getMessage(), failCausedBy); } } } diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/MetadataTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/MetadataTracker.java index ed6fc6da6..8636c9c71 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/MetadataTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/MetadataTracker.java @@ -1039,9 +1039,9 @@ public class MetadataTracker extends CoreStatePublisher implements Tracker } @Override - protected void onFail() + protected void onFail(Throwable failCausedBy) { - setRollback(true); + setRollback(true, failCausedBy); } private List filterNodes(List nodes) diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/Tracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/Tracker.java index 976d52c20..b7e049fa5 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/Tracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/Tracker.java @@ -41,9 +41,11 @@ public interface Tracker boolean getRollback(); + Throwable getRollbackCausedBy(); + Properties getProps(); - void setRollback(boolean rollback); + void setRollback(boolean rollback, Throwable rollbackCausedBy); void invalidateState(); diff --git a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/AlfrescoSolrTrackerRollbackIT.java b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/AlfrescoSolrTrackerRollbackIT.java index 2313586ac..9baf19990 100644 --- a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/AlfrescoSolrTrackerRollbackIT.java +++ b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/AlfrescoSolrTrackerRollbackIT.java @@ -195,7 +195,7 @@ public class AlfrescoSolrTrackerRollbackIT extends AbstractAlfrescoSolrIT //This will prove the rollback transaction was rolled back SOLRAPIQueueClient.transactionQueue.remove(rollbackTxn); - metadataTracker.setRollback(true); + metadataTracker.setRollback(true, new Exception("Forced rollback!")); commitTracker.getRunLock().release();