Adding objectTrace logger to output configurable fields to a new log …

…file from PickUpPlace (#530)

src/main/config/logback.xml

@@ -48,6 +48,34 @@
     </then>
   </if>
 
+  <!-- Enable output metrics logging by creating an environment variable of "ObjectTrace=true" -->
+  <if condition="&quot;${ObjectTrace}&quot;.equals(&quot;true&quot;)">
+    <then>
+      <appender name="OBJECT-TRACE" class="emissary.util.CustomRolloverLogbackAppender">
+        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
+          <customFields>{"node":"${emissary.node.name}"}</customFields>
+          <includeMdc>false</includeMdc>
+          <fieldNames>
+            <version>[ignore]</version>
+            <logger>[ignore]</logger>
+            <thread>[ignore]</thread>
+            <levelValue>[ignore]</levelValue>
+            <level>[ignore]</level>
+            <message>[ignore]</message>
+          </fieldNames>
+        </encoder>
+        <file>logs/${emissary.node.name}-${emissary.node.port}-object-trace.log</file>
+        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+          <fileNamePattern>logs/${emissary.node.name}-${emissary.node.port}-object-trace.log.%d{yyyyMMdd-HHmm}</fileNamePattern>
+        </rollingPolicy>
+      </appender>
+
+      <logger name="objectTrace" level="INFO" additivity="false">
+        <appender-ref ref="OBJECT-TRACE" />
+      </logger>
+    </then>
+  </if>
+
   <root level="INFO">
     <!-- stop logging to a file in development man, redirect or tee to a file
     <appender-ref ref="TOFILE"/>

src/main/java/emissary/pickup/PickUpPlace.java

@@ -17,6 +17,7 @@
 import emissary.place.ServiceProviderPlace;
 import emissary.pool.AgentPool;
 import emissary.util.ClassComparator;
+import emissary.util.ObjectTracing;
 import emissary.util.TimeUtil;
 import emissary.util.shell.Executrix;
 
@@ -75,6 +76,9 @@ public abstract class PickUpPlace extends ServiceProviderPlace implements IPickU
     // Metadata items that should always be copied to children
     protected Set<String> ALWAYS_COPY_METADATA_VALS = new HashSet<>();
 
+    private boolean useObjectTraceLogger = false;
+    protected ObjectTracing objectTracingUtil;
+
     public PickUpPlace() throws IOException {
         super();
         configurePickUpPlace();
@@ -178,6 +182,13 @@ protected void configurePickUpPlace() {
         }
 
         ALWAYS_COPY_METADATA_VALS = configG.findEntriesAsSet("ALWAYS_COPY_METADATA");
+
+        // Setup objectTraceLogger
+        useObjectTraceLogger = configG.findBooleanEntry("USE_OBJECT_TRACE_LOGGER", useObjectTraceLogger);
+        if (useObjectTraceLogger) {
+            objectTracingUtil = new ObjectTracing();
+            logger.info("Setting up the object trace logger");
+        }
     }
 
     /**
@@ -550,6 +561,12 @@ protected boolean processDataObject(IBaseDataObject d, String fixedName, File th
         dataObjectCreated(d, theFile);
         logger.info("**Deploying an agent for {} and object {} forms={} simple={}", fixedName, d.getInternalId(), d.getAllCurrentForms(),
                 (simpleMode ? "simple" : ""));
+
+        // If object tracing log that agent is being deployed for fixedName (filename)
+        if (useObjectTraceLogger) {
+            objectTracingUtil.emitLifecycleEvent(d, ObjectTracing.Stage.PickUp);
+        }
+
         assignToPooledAgent(d, -1L);
         return true;
     }

src/main/java/emissary/util/CustomRolloverLogbackAppender.java

@@ -0,0 +1,44 @@
+package emissary.util;
+
+import emissary.config.ConfigUtil;
+import emissary.config.Configurator;
+
+import ch.qos.logback.core.rolling.RollingFileAppender;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import java.io.IOException;
+
+public class CustomRolloverLogbackAppender<E> extends RollingFileAppender<E> {
+    private long start = System.currentTimeMillis();
+    private int rolloverTime = 15;
+    private boolean isConfigured = false;
+
+    protected static final Logger logger = LoggerFactory.getLogger(CustomRolloverLogbackAppender.class);
+
+    public void configure() {
+        try {
+            Configurator configG = ConfigUtil.getConfigInfo(getClass());
+            rolloverTime = configG.findIntEntry("ROLLOVER_TIME_MINUTES", rolloverTime);
+        } catch (IOException e) {
+            logger.error("Could not read from the config for the CustomRolloverLogbackAppender ", e);
+        }
+    }
+
+    @Override
+    public void rollover() {
+
+        if (!isConfigured) {
+            configure();
+            isConfigured = true;
+        }
+
+        long currentTime = System.currentTimeMillis();
+        int maxIntervalSinceLastLoggingInMillis = rolloverTime * 60 * 1000;
+
+        if ((currentTime - start) >= maxIntervalSinceLastLoggingInMillis) {
+            super.rollover();
+            start = System.currentTimeMillis();
+        }
+    }
+}

src/main/java/emissary/util/ObjectTracing.java

@@ -0,0 +1,33 @@
+package emissary.util;
+
+import emissary.core.IBaseDataObject;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import java.util.HashMap;
+import java.util.Map;
+
+import static net.logstash.logback.marker.Markers.appendEntries;
+
+public class ObjectTracing {
+
+    protected static Logger objectTraceLogger = LoggerFactory.getLogger("objectTrace");;
+
+    public enum Stage {
+        PickUp, DropOff
+    }
+
+    public ObjectTracing() {}
+
+    public void emitLifecycleEvent(IBaseDataObject d, ObjectTracing.Stage stage) {
+
+        Map<String, String> jsonMap = new HashMap<>();
+
+        // add our fields
+        jsonMap.put("inputFileName", d.getFilename());
+        jsonMap.put("stage", String.valueOf(stage));
+
+        objectTraceLogger.info(appendEntries(jsonMap), "");
+    }
+}

src/main/resources/emissary/pickup/file/FilePickUpPlace.cfg

@@ -34,4 +34,4 @@ UNIX_OUT_ROOT = "@{OUTPUT_DATA}"
 MINIMUM_DATA_SIZE = "-1"
 MAXIMUM_DATA_SIZE = "-1"
 
-
+USE_OBJECT_TRACE_LOGGER = true

src/main/resources/emissary/util/CustomRolloverLogbackAppender.cfg

@@ -0,0 +1 @@
+ROLLOVER_TIME_MINUTES = 15