Merge "Omaha #4129 Log active table changes from ingestAT" into omaha_14.4.1

Former-commit-id: eaecbaa0b66153b43bfe59f96c43a1876b9e235f

edexOsgi/build.edex/esb/conf/logback.xml

@@ -22,6 +22,30 @@
       </encoder> 
    </appender>
 
+   <!-- activeTableChange log --> 
+   <!-- When migrating this change to 15.1.1 it will need to be split up properly.
+        See Roger Ferrel for instruction 
+    -->
+   <appender name="activeTableChangeLog" class="ch.qos.logback.core.rolling.RollingFileAppender">
+      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+         <fileNamePattern>${edex.home}/logs/edex-${edex.run.mode}-activeTableChange-%d{yyyyMMdd}.log</fileNamePattern>
+         <maxHistory>30</maxHistory>
+      </rollingPolicy> 
+
+      <encoder> 
+         <pattern>%-5p %d [%t] %c{0}: %m%n</pattern> 
+      </encoder>
+   </appender> 
+   
+   <appender name="activeTableChangeLogAsync" class="ch.qos.logback.classic.AsyncAppender">            
+      <appender-ref ref="activeTableChangeLog" />
+   </appender> 
+
+   <logger name="ActiveTableChange" additivity="false">
+      <level value="DEBUG"/>
+      <appender-ref ref="activeTableChangeLogAsync" />
+   </logger>
+      
    <!-- ProductSrvRequest log --> 
    <appender name="ProductSrvRequestLog" class="ch.qos.logback.core.rolling.RollingFileAppender">
       <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">

edexOsgi/com.raytheon.edex.plugin.gfe/utility/edex_static/base/gfe/isc/iscDataRec.py

@@ -196,7 +196,7 @@ def execIscDataRec(MSGID,SUBJECT,FILES):
                 elif SUBJECT == 'GET_ACTIVE_TABLE':
                     IrtServer.getVTECActiveTable(dataFile, None)
                 elif SUBJECT == 'GET_ACTIVE_TABLE2':
-                    IrtServer.getVTECActiveTable(dateFile, xmlFileBuf) 
+                    IrtServer.getVTECActiveTable(dataFile, xmlFileBuf) 
                 elif SUBJECT in ['ISCGRIDS', 'ISCGRIDS2']:
                     args = {"siteID": siteConfig.GFESUITE_SITEID, 
                             "userID": 'SITE', 

edexOsgi/com.raytheon.uf.edex.activetable/src/com/raytheon/uf/edex/activetable/ActiveTable.java

@@ -100,6 +100,7 @@ import com.raytheon.uf.edex.database.query.DatabaseQuery;
  *                                     Pass issuance site id to getActiveTable() 
  *                                     in updateActiveTable() so records will
  *                                     be updated correctly.
+ * Mar 04, 2015    4129    randerso    Pass active table change logger to ingestAt and/or MergeVTEC
  * 
  * </pre>
  * 
@@ -300,7 +301,8 @@ public class ActiveTable {
                     .getHandler("ActiveTable");
             ITimer timer = TimeUtil.getTimer();
             timer.start();
-            List<ActiveTableRecord> activeTable = getActiveTable(issueSiteId, mode);
+            List<ActiveTableRecord> activeTable = getActiveTable(issueSiteId,
+                    mode);
             timer.stop();
             perfStat.logDuration("getActiveTable", timer.getElapsedTime());
 
@@ -589,6 +591,7 @@ public class ActiveTable {
                 args.put("newRecords", newRecords);
                 args.put("drt", timeOffset);
                 args.put("makeBackups", makeBackup);
+                args.put("atChangeLog", changeLog);
                 if (runIngestAT) {
                     args.put("xmlIncoming", xmlSource);
                 }

edexOsgi/com.raytheon.uf.edex.activetable/utility/common_static/base/vtec/MergeVTEC.py

@@ -35,8 +35,10 @@
 #    01/24/14        #2504         randerso       change to use iscUtil.getLogger for consistency 
 #    03/25/14        #2884         randerso       Added xxxid to VTECChange
 #    05/15/14        #3157         dgilling       Support multiple TPC and SPC sites.
+#    03/04/2015      #4129         randerso       Log the active table changes at info level 
+#                                                 in the active table change log
 #
-
+##
 
 import copy
 import cPickle
@@ -64,7 +66,7 @@ from com.raytheon.uf.common.activetable import VTECPartners as JavaVTECPartners
 class MergeVTEC(VTECTableUtil.VTECTableUtil):
 
     def __init__(self, activeTable, activeTableMode, newRecords, offsetSecs=0.0, 
-      makeBackups=True, logger=None):
+      makeBackups=True, logger=None, atChangeLog=None):
         # activeTable - current activeTable records
         # activeTableMode - which table is being modified--OPERATIONAL or PRACTICE
         # newRecords - records to merge in to activeTable
@@ -125,7 +127,7 @@ class MergeVTEC(VTECTableUtil.VTECTableUtil):
         self._log.info("Other Table squeezed size: %d", len(otherTable))
 
         #merge the tables
-        updatedTable, toDelete, changes = self._mergeTable(activeTable, otherTable)
+        updatedTable, toDelete, changes = self._mergeTable(activeTable, otherTable, atChangeLog)
         self._log.info("Updated Active Table size: %d", len(updatedTable))
         updatedTable, tossRecordsMerged = vts.squeeze(updatedTable)
         self._log.info("Updated Active Table squeeze size: %d", 
@@ -161,7 +163,7 @@ class MergeVTEC(VTECTableUtil.VTECTableUtil):
 
     # merges the active and other table together and returns the merged
     # table along with the list of changes that occurred.
-    def _mergeTable(self, activeTable, otherTable):
+    def _mergeTable(self, activeTable, otherTable, atChangeLog):
         changes = []
         purges = []
         compare = ['id', 'phen', 'sig', 'officeid', 'etn', 'pil']
@@ -342,30 +344,31 @@ class MergeVTEC(VTECTableUtil.VTECTableUtil):
                         changes.append(chgRec)
                     
         # log the changes
-        if len(missingEntriesAct):
+        if atChangeLog is not None:
-            self._log.debug("Active Missing entries added: %s",
+            if len(missingEntriesAct):
-              self.printActiveTable(missingEntriesAct, 1))
+                atChangeLog.info("Active Missing entries added: " +
-        if len(newReplaceEntriesAct):
+                  self.printActiveTable(missingEntriesAct, 1))
-            self._log.debug("Active Replacement entries (new): %s",
+            if len(newReplaceEntriesAct):
-              self.printActiveTable(newReplaceEntriesAct, 1))
+                atChangeLog.info("Active Replacement entries (new): " +
-        if len(oldReplaceEntriesAct):
+                  self.printActiveTable(newReplaceEntriesAct, 1))
-            self._log.debug("Active Entries Replaced (old): %s",
+            if len(oldReplaceEntriesAct):
-              self.printActiveTable(oldReplaceEntriesAct, 1))
+                atChangeLog.info("Active Entries Replaced (old): " +
-        if len(missingEntriesPast):
+                  self.printActiveTable(oldReplaceEntriesAct, 1))
-            self._log.debug("Past Missing entries added %s",
+            if len(missingEntriesPast):
-              self.printActiveTable(missingEntriesPast, 1))
+                atChangeLog.info("Past Missing entries added " +
-        if len(newReplaceEntriesPast):
+                  self.printActiveTable(missingEntriesPast, 1))
-            self._log.debug("Past Replacement entries (new): %s",
+            if len(newReplaceEntriesPast):
-              self.printActiveTable(newReplaceEntriesPast, 1))
+                atChangeLog.info("Past Replacement entries (new): " +
-        if len(oldReplaceEntriesPast):
+                  self.printActiveTable(newReplaceEntriesPast, 1))
-            self._log.debug("Past Entries Replaced (old): %s",
+            if len(oldReplaceEntriesPast):
-              self.printActiveTable(oldReplaceEntriesPast, 1))
+                atChangeLog.info("Past Entries Replaced (old): " +
-        if len(ignoredNewReplaceAct):
+                  self.printActiveTable(oldReplaceEntriesPast, 1))
-            self._log.debug("Ignored Different Year Issuance (new): %s",
+            if len(ignoredNewReplaceAct):
-              self.printActiveTable(ignoredNewReplaceAct, 1))
+                atChangeLog.info("Ignored Different Year Issuance (new): " +
-            self._log.debug("Ignored Different Year Issuance (old): %s",
+                  self.printActiveTable(ignoredNewReplaceAct, 1))
-              self.printActiveTable(ignoredOldReplaceAct, 1))
+                atChangeLog.info("Ignored Different Year Issuance (old): " +
-        self._log.debug("Table Changes: %s", changes)
+                  self.printActiveTable(ignoredOldReplaceAct, 1))
+            atChangeLog.info("Table Changes: " + str(changes))
         
         purges.extend(oldReplaceEntriesAct)
         purges.extend(oldReplaceEntriesPast)
@@ -411,7 +414,7 @@ class MergeVTEC(VTECTableUtil.VTECTableUtil):
         return iscUtil.getLogger("MergeVTEC", logLevel=logging.INFO)
 
 def merge(activeTable, activeTableMode, newRecords, drt=0.0, makeBackups=True,
-      logger=None):
+      logger=None, atChangeLog=None):
     pyActive = []
     for i in range(activeTable.size()):
         pyActive.append(ActiveTableRecord.ActiveTableRecord(activeTable.get(i)))
@@ -420,7 +423,7 @@ def merge(activeTable, activeTableMode, newRecords, drt=0.0, makeBackups=True,
     for i in range(newRecords.size()):
         pyNew.append(ActiveTableRecord.ActiveTableRecord(newRecords.get(i)))
     
-    decoder = MergeVTEC(pyActive, activeTableMode, pyNew, drt, makeBackups, logger)
+    decoder = MergeVTEC(pyActive, activeTableMode, pyNew, drt, makeBackups, logger, atChangeLog)
     mergeResults = decoder.getMergeResults()
     decoder = None
     

edexOsgi/com.raytheon.uf.edex.activetable/utility/common_static/base/vtec/ingestAT.py

@@ -28,7 +28,9 @@
 #    ------------    ----------    -----------    --------------------------
 #    02/13/13        1447          dgilling       Initial Creation.
 #    01/24/14        2504          randerso       change to use iscUtil.getLogger for consistency 
+#    03/04/2015      4129          randerso       Pass active table change logger through to MergeVtec.merge
 #
+##
 
 
 import os
@@ -48,7 +50,7 @@ def init_logging():
     logger = iscUtil.getLogger("ingestAT", logLevel=logging.INFO)
 
 
-def execute_ingest_at(incomingRecords, activeTable, atName, ztime, makeBackups, xmlIncoming):
+def execute_ingest_at(incomingRecords, activeTable, atName, ztime, makeBackups, xmlIncoming, atChangeLog):
     # log the source of this data
     if xmlIncoming is not None:
         irt = IrtAccess.IrtAccess("")
@@ -63,20 +65,20 @@ def execute_ingest_at(incomingRecords, activeTable, atName, ztime, makeBackups,
     results = None        
     try:
         results = MergeVTEC.merge(activeTable, atName, incomingRecords, ztime, makeBackups,
-          logger)
+          logger, atChangeLog)
     except:
         logger.exception("MergeVTEC fail:")
     return results
 
 def runFromJava(activeTable, activeTableMode, newRecords, drt, makeBackups,
-                xmlIncoming):
+                xmlIncoming, atChangeLog=None):
     init_logging()
     
     logger.info('************* ingestAT ************************')
     startT = time.time()
     
     results = execute_ingest_at(newRecords, activeTable, activeTableMode, drt,
-                      makeBackups, xmlIncoming)
+                      makeBackups, xmlIncoming, atChangeLog=atChangeLog)
     
     #--------------------------------------------------------------------
     # Finish