inteligr8/SearchServices
1
0
Fork 0
mirror of https://github.com/Alfresco/SearchServices.git synced 2026-09-16 18:12:56 +00:00
Code Issues Packages Projects Releases Wiki Activity

Merge branch 'feature/SEARCH-2097_ACLTrackerLog' into 'master'

Browse Source 
SEARCH-2097: Adding verbose log (INFO, DEBUG and TRACE levels) for AclTracker.

See merge request search_discovery/insightengine!399
This commit is contained in:
Angel Borroy
2020-03-09 11:34:27 +00:00
parent 6e3bf14f05 7e91e77eae
commit 02a0993ac3
10 changed files with 137 additions and 74 deletions
Download Patch File Download Diff File Expand all files Collapse all files
search-services/alfresco-search/src/main/java/org/alfresco/solr/SolrInformationServer.java
+2 -1
View File
@@ -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
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractTracker.java
+20 -15
View File
@@ -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()
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AbstractWorkerRunnable.java
+5 -3
View File
@@ -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);
}
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/AclTracker.java
+84 -43
View File
@@ -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<AclReaders> 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<AclChangeSet> changeSetBatch = new ArrayList<AclChangeSet>();
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<Acl> aclBatch = new ArrayList<Acl>();
List<Acl> 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<Acl> filterAcls(List<Acl> acls)
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CascadeTracker.java
+2 -2
View File
@@ -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);
}
}
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CommitTracker.java
+15 -4
View File
@@ -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
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ContentTracker.java
+3 -2
View File
@@ -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);
}
}
}
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/MetadataTracker.java
+2 -2
View File
@@ -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<Node> filterNodes(List<Node> nodes)
search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/Tracker.java
+3 -1
View File
@@ -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();
search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/AlfrescoSolrTrackerRollbackIT.java
+1 -1
View File
@@ -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();