From 0f0576812464d3f3e8bab19a541afcc769cb4006 Mon Sep 17 00:00:00 2001 From: agazzarini Date: Wed, 15 Apr 2020 11:59:43 +0200 Subject: [PATCH] [ SEARCH-2182 ] Simplest approach for logging core, tracker type, instance and iteration id --- .../solr/tracker/AbstractTracker.java | 37 +++++++++++-------- .../org/alfresco/solr/tracker/AclTracker.java | 2 +- .../alfresco/solr/tracker/CascadeTracker.java | 24 +++++++++--- .../alfresco/solr/tracker/CommitTracker.java | 2 +- .../alfresco/solr/tracker/ContentTracker.java | 2 +- .../solr/tracker/CoreStatePublisher.java | 6 +-- .../solr/tracker/MetadataTracker.java | 2 +- .../alfresco/solr/tracker/ModelTracker.java | 10 ++--- .../solr/tracker/SlaveCoreStatePublisher.java | 4 +- .../solr/tracker/ContentTrackerIT.java | 4 +- .../solr/tracker/MetadataTrackerTest.java | 4 +- .../alfresco/solr/tracker/ModelTrackerIT.java | 2 +- 12 files changed, 58 insertions(+), 41 deletions(-) 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 47930d6c0..d0a19474f 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 @@ -20,7 +20,6 @@ package org.alfresco.solr.tracker; import static java.util.Optional.ofNullable; -import java.lang.invoke.MethodHandles; import java.net.ConnectException; import java.net.SocketTimeoutException; import java.util.Properties; @@ -45,7 +44,7 @@ public abstract class AbstractTracker implements Tracker static final long TIME_STEP_1_HR_IN_MS = 60 * 60 * 1000L; static final String SHARD_METHOD_DBID = "DB_ID"; - protected final static Logger LOGGER = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + protected final Logger logger = LoggerFactory.getLogger(getClass()); protected Properties props; protected SOLRAPIClient client; @@ -73,6 +72,7 @@ public abstract class AbstractTracker implements Tracker */ protected Throwable rollbackCausedBy; protected final Type type; + protected final String trackerId; /* * A thread handler can be used by subclasses, but they have to intentionally instantiate it. @@ -85,8 +85,9 @@ public abstract class AbstractTracker implements Tracker protected AbstractTracker(Type type) { this.type = type; + this.trackerId = type + "@" + hashCode(); } - + protected AbstractTracker(Properties p, SOLRAPIClient client, String coreName, InformationServer informationServer,Type type) { this.props = p; @@ -109,6 +110,8 @@ public abstract class AbstractTracker implements Tracker this.trackerStats = this.infoSrv.getTrackerStats(); this.type = type; + + this.trackerId = type + "@" + hashCode(); } @@ -121,8 +124,10 @@ public abstract class AbstractTracker implements Tracker *
  • Index
    • *
  • Track repository
    • * + * + * @param iterationId an identifier which is uniquely associated with a given iteration. */ - protected abstract void doTrack() throws Throwable; + protected abstract void doTrack(String iterationId) throws Throwable; private boolean assertTrackerStateRemainsNull() { @@ -156,14 +161,16 @@ public abstract class AbstractTracker implements Tracker } /** * Template method - subclasses must implement the {@link Tracker}-specific indexing - * by implementing the abstract method {@link #doTrack()}. + * by implementing the abstract method {@link #doTrack(String)}. */ @Override public void track() { + String iterationId = "IT #" + System.currentTimeMillis(); + if(runLock.availablePermits() == 0) { - LOGGER.info("... {} for core [{}] is already in use {}", this.getClass().getSimpleName(), coreName, getClass()); + logger.info("[{} / {} / {}] Tracker already registered.", coreName, trackerId, iterationId); return; } @@ -180,13 +187,11 @@ public abstract class AbstractTracker implements Tracker assert(assertTrackerStateRemainsNull()); } - LOGGER.info("[CORE {}] Running {}", coreName, this.getClass().getSimpleName()); - if(this.state == null) { this.state = getTrackerState(); - LOGGER.debug("[CORE {}] Global Tracker State set to: {}", coreName, this.state.toString()); + logger.debug("[{} / {} / {}] Global Tracker State set to: {}", coreName, trackerId, iterationId, this.state.toString()); this.state.setRunning(true); } else @@ -199,33 +204,33 @@ public abstract class AbstractTracker implements Tracker try { - doTrack(); + doTrack(iterationId); } catch(IndexTrackingShutdownException t) { setRollback(true, t); - LOGGER.info("[CORE {}] Stopping index tracking for {}", coreName, getClass().getSimpleName()); + logger.info("[{} / {} / {}] Tracking cycle stopped. See the stacktrace below for further details.", coreName, trackerId, iterationId, t); } catch(Throwable t) { setRollback(true, t); if (t instanceof SocketTimeoutException || t instanceof ConnectException) { - LOGGER.warn("[CORE {}] Tracking communication timed out for {}", coreName, getClass().getSimpleName()); - if (LOGGER.isDebugEnabled()) + logger.warn("[{} / {} / {}] Tracking communication timed out. See the stacktrace below for further details.", coreName, trackerId, iterationId); + if (logger.isDebugEnabled()) { - LOGGER.debug("[CORE {}] Stack trace", coreName, t); + logger.debug("[{} / {} / {}] Stack trace", coreName, trackerId, iterationId, t); } } else { - LOGGER.error("[CORE {}] Tracking failed for {}", coreName, getClass().getSimpleName(), t); + logger.error("[{} / {} / {}] Tracking failure. See the stacktrace below for further details.", coreName, trackerId, iterationId, t); } } } catch (InterruptedException e) { - LOGGER.error("[CORE {}] Semaphore interrupted for {}", coreName, getClass().getSimpleName(), e); + logger.error("[{} / {} / {}] Semaphore interruption. See the stacktrace below for further details.", coreName, trackerId, iterationId, e); } finally { 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 e28785c7a..722e6ba26 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 @@ -90,7 +90,7 @@ public class AclTracker extends AbstractTracker } @Override - protected void doTrack() throws Throwable + protected void doTrack(String iterationId) throws Throwable { trackRepository(); } 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 18e79394f..6396500d4 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 @@ -36,6 +36,9 @@ import org.json.JSONException; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import static java.util.stream.Collectors.joining; +import static org.alfresco.solr.utils.Utils.notNullOrEmpty; + /* * This tracks Cascading Updates * @author Joel Bernstein @@ -61,13 +64,13 @@ public class CascadeTracker extends AbstractTracker implements Tracker } @Override - protected void doTrack() throws AuthenticationException, IOException, JSONException, EncoderException + protected void doTrack(String iterationId) throws AuthenticationException, IOException, JSONException, EncoderException { // MetadataTracker must wait until ModelTracker has run ModelTracker modelTracker = this.infoSrv.getAdminHandler().getTrackerRegistry().getModelTracker(); if (modelTracker != null && modelTracker.hasModels()) { - trackRepository(); + trackRepository(iterationId); } } @@ -79,10 +82,10 @@ public class CascadeTracker extends AbstractTracker implements Tracker return false; } - private void trackRepository() throws IOException, AuthenticationException, JSONException, EncoderException + private void trackRepository(String iterationId) throws IOException, AuthenticationException, JSONException, EncoderException { checkShutdown(); - processCascades(); + processCascades(iterationId); } private void updateTransactionsAfterAsynchronous(List txsIndexed) @@ -125,9 +128,8 @@ public class CascadeTracker extends AbstractTracker implements Tracker infoSrv.setCleanCascadeTxnFloor(-1); } - private void processCascades() throws IOException + private void processCascades(String iterationId) throws IOException { - //System.out.println("######### processCascades()"); int num = 50; List txBatch = null; do { @@ -160,7 +162,17 @@ public class CascadeTracker extends AbstractTracker implements Tracker batch.add(stack.removeFirst()); } + CascadeIndexWorkerRunnable worker = new CascadeIndexWorkerRunnable(this.threadHandler, batch, infoSrv); + + if (logger.isTraceEnabled()) + { + String nodes = notNullOrEmpty(batch).stream() + .map(NodeMetaData::getId) + .map(Object::toString) + .collect(joining(",")); + logger.trace("[{} / {} / {} / {}] Worker has been created for nodes {}", coreName, trackerId, iterationId, worker.hashCode(), nodes); + } this.threadHandler.scheduleTask(worker); } while (stack.size() > 0); 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 e087752b2..fa2b2ee06 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 @@ -101,7 +101,7 @@ public class CommitTracker extends AbstractTracker } @Override - protected void doTrack() throws Throwable + protected void doTrack(String iterationId) throws Throwable { long currentTime = System.currentTimeMillis(); boolean commitNeeded = false; 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 e4b837280..534b1d7e2 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 @@ -57,7 +57,7 @@ public class ContentTracker extends AbstractTracker implements Tracker } @Override - protected void doTrack() throws Exception + protected void doTrack(String iterationId) throws Exception { //System.out.println("############## Content Tracker doTrack()"); try { diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CoreStatePublisher.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CoreStatePublisher.java index 591863964..aec77956c 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CoreStatePublisher.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/CoreStatePublisher.java @@ -118,7 +118,7 @@ public abstract class CoreStatePublisher extends AbstractTracker updateShardProperty(); if (shardProperty.isEmpty()) { - LOGGER.warn("Sharding property {} was set to {}, but no such property was found.", SHARD_KEY_KEY, shardKeyName); + logger.warn("Sharding property {} was set to {}, but no such property was found.", SHARD_KEY_KEY, shardKeyName); } }); } @@ -134,11 +134,11 @@ public abstract class CoreStatePublisher extends AbstractTracker { if (updatedShardProperty.isEmpty()) { - LOGGER.warn("The model defining {} property has been disabled", shardKeyName); + logger.warn("The model defining {} property has been disabled", shardKeyName); } else { - LOGGER.info("New {} property found for {} ", SHARD_KEY_KEY, shardKeyName); + logger.info("New {} property found for {} ", SHARD_KEY_KEY, shardKeyName); } } shardProperty = updatedShardProperty; 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 8636c9c71..551599fef 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 @@ -169,7 +169,7 @@ public class MetadataTracker extends CoreStatePublisher implements Tracker } @Override - protected void doTrack() throws AuthenticationException, IOException, JSONException, EncoderException + protected void doTrack(String iterationId) throws AuthenticationException, IOException, JSONException, EncoderException { log.debug("### MetadataTracker doTrack ###"); // MetadataTracker must wait until ModelTracker has run diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ModelTracker.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ModelTracker.java index 034d14228..946634c3c 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ModelTracker.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/ModelTracker.java @@ -106,7 +106,7 @@ public class ModelTracker extends AbstractTracker implements Tracker super(p, client, coreName, informationServer, Tracker.Type.MODEL); String normalSolrHome = SolrResourceLoader.normalizeDir(solrHome); alfrescoModelDir = new File(ConfigUtil.locateProperty("solr.model.dir", normalSolrHome+"alfrescoModels")); - LOGGER.info("Alfresco Model dir " + alfrescoModelDir); + logger.info("Alfresco Model dir " + alfrescoModelDir); if (!alfrescoModelDir.exists()) { alfrescoModelDir.mkdir(); @@ -191,13 +191,13 @@ public class ModelTracker extends AbstractTracker implements Tracker } @Override - protected void doTrack() throws AuthenticationException, IOException, JSONException + protected void doTrack(String iterationId) throws AuthenticationException, IOException, JSONException { // Is the InformationServer ready to update int registeredSearcherCount = this.infoSrv.getRegisteredSearcherCount(); if (registeredSearcherCount >= getMaxLiveSearchers()) { - LOGGER.info(".... skipping tracking registered searcher count = " + registeredSearcherCount); + logger.info(".... skipping tracking registered searcher count = " + registeredSearcherCount); return; } @@ -268,7 +268,7 @@ public class ModelTracker extends AbstractTracker implements Tracker } catch (Throwable t) { - LOGGER.error("Model tracking failed for core: "+ coreName, t); + logger.error("Model tracking failed for core: "+ coreName, t); } } @@ -534,7 +534,7 @@ public class ModelTracker extends AbstractTracker implements Tracker { loadedModels.add(modelName); } - LOGGER.info("Loading model " + model.getName()); + logger.info("Loading model " + model.getName()); } } diff --git a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/SlaveCoreStatePublisher.java b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/SlaveCoreStatePublisher.java index 71750c53f..39e4ff3d2 100644 --- a/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/SlaveCoreStatePublisher.java +++ b/search-services/alfresco-search/src/main/java/org/alfresco/solr/tracker/SlaveCoreStatePublisher.java @@ -58,7 +58,7 @@ public class SlaveCoreStatePublisher extends CoreStatePublisher } @Override - protected void doTrack() + protected void doTrack(String iterationId) { try { @@ -67,7 +67,7 @@ public class SlaveCoreStatePublisher extends CoreStatePublisher } catch (EncoderException | IOException | AuthenticationException exception ) { - LOGGER.error("Unable to publish this node state. " + + logger.error("Unable to publish this node state. " + "A failure condition has been met during the outbound subscription message encoding process. " + "See the stacktrace below for further details.", exception); } diff --git a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ContentTrackerIT.java b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ContentTrackerIT.java index 517a5f241..b3e713665 100644 --- a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ContentTrackerIT.java +++ b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ContentTrackerIT.java @@ -71,7 +71,7 @@ public class ContentTrackerIT public void doTrackWithNoContentDoesNothing() throws Exception { - this.contentTracker.doTrack(); + this.contentTracker.doTrack("anIterationId"); verify(srv, never()).updateContentToIndexAndCache(anyLong(), anyString()); verify(srv, never()).commit(); } @@ -107,7 +107,7 @@ public class ContentTrackerIT .thenReturn(docs1) .thenReturn(docs2) .thenReturn(emptyList); - this.contentTracker.doTrack(); + this.contentTracker.doTrack("anIterationId"); InOrder order = inOrder(srv); order.verify(srv).getDocsWithUncleanContent(0, READ_BATCH); diff --git a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/MetadataTrackerTest.java b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/MetadataTrackerTest.java index 7d2c4c1ce..b3b4d56fd 100644 --- a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/MetadataTrackerTest.java +++ b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/MetadataTrackerTest.java @@ -117,7 +117,7 @@ public class MetadataTrackerTest nodes.add(node ); when(repositoryClient.getNodes(any(GetNodesParameters.class), anyInt())).thenReturn(nodes); - this.metadataTracker.doTrack(); + this.metadataTracker.doTrack("AnIterationId"); InOrder inOrder = inOrder(srv); inOrder.verify(srv).indexNodes(nodes, true); @@ -141,7 +141,7 @@ public class MetadataTrackerTest when(repositoryClient.getTransactions(anyLong(), anyLong(), anyLong(), anyLong(), anyInt(), any(ShardState.class))).thenReturn(txs); when(repositoryClient.getTransactions(anyLong(), anyLong(), anyLong(), anyLong(), anyInt())).thenReturn(txs); - this.metadataTracker.doTrack(); + this.metadataTracker.doTrack("AnIterationId"); verify(srv, never()).commit(); } diff --git a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ModelTrackerIT.java b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ModelTrackerIT.java index b0a64fe97..5259f300b 100644 --- a/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ModelTrackerIT.java +++ b/search-services/alfresco-search/src/test/java/org/alfresco/solr/tracker/ModelTrackerIT.java @@ -118,7 +118,7 @@ public class ModelTrackerIT public void testDoTrack() throws AuthenticationException, IOException, JSONException { ModelTracker spiedModelTracker = spy(this.modelTracker); - spiedModelTracker.doTrack(); + spiedModelTracker.doTrack("AnIterationId"); verify(this.srv).getRegisteredSearcherCount(); verify(spiedModelTracker).trackModels(false);