[ SEARCH-2182 ] Simplest approach for logging core, tracker type, instance and iteration id

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
      *     <li>Index</li>
      *     <li>Track repository</li>
      * </ol>
+     *
+     * @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
         {

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();
     }

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<Transaction> 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<Transaction> 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);

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;

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 {

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;

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

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());
         }
     }
 

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);
         }

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);

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();
     }

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);