demoting more messages to de-clutter info

sarracenia/flow/__init__.py

@@ -243,7 +243,7 @@ def loadCallbacks(self, plugins_to_load=None):
                 logger.debug( "details:", exc_info=True )
                 return False
 
-        logger.info( f'flowCallback plugins to load: {plugins_to_load}' )
+        logger.debug( f'flowCallback plugins to load: {plugins_to_load}' )
         for c in plugins_to_load:
             try:
                 plugin = sarracenia.flowcb.load_library(c, self.o)
@@ -301,7 +301,6 @@ def runCallbacksTime(self, entry_point):
                 eval( f"self.{entry_point}()")
             else:
                 try:
-                    logger.info( f'normal run of self.{entry_point}' )
                     eval( f"self.{entry_point}()")
                 except Exception as ex:
                     logger.error( f'flow {entry_point} crashed: {ex}' )
@@ -446,9 +445,7 @@ def reject(self, m, code, reason) -> None:
         m.setReport(code, reason)
 
     def please_stop(self) -> None:
-        logger.info(
-            f'ok, telling {len(self.plugins["please_stop"])} callbacks about it.'
-        )
+        logger.info( f'ok, telling {len(self.plugins["please_stop"])} callbacks about it.')
         self._stop_requested = True
         self.metrics["flow"]['stop_requested'] = True
 
@@ -528,8 +525,8 @@ def run(self):
             logger.debug("options:")
             self.o.dump()
 
-        logger.info("callbacks loaded: %s" % self.plugins['load'])
-        logger.info(
+        logger.debug("callbacks loaded: %s" % self.plugins['load'])
+        logger.debug(
             f'pid: {os.getpid()} {self.o.component}/{self.o.config} instance: {self.o.no}'
         )
 
@@ -541,11 +538,11 @@ def run(self):
 
             if self._stop_requested:
                 if stopping:
-                    logger.info('clean stop from run loop')
+                    logger.debug('clean stop from run loop')
                     self.close()
                     break
                 else:
-                    logger.info( 'starting last pass (without gather) through loop for cleanup.')
+                    logger.debug( 'starting last pass (without gather) through loop for cleanup.')
                     stopping = True
 
             self._run_vip_update()
@@ -598,7 +595,7 @@ def run(self):
             if (last_gather_len == 0) and (self.o.sleep < 0):
                 if (self.o.retryEmptyBeforeExit and "retry" in self.metrics
                     and self.metrics['retry']['msgs_in_post_retry'] > 0):
-                    logger.info("Not exiting because there are still messages in the post retry queue.")
+                    logger.debug("Not exiting because there are still messages in the post retry queue.")
                     # Sleep for a while. Messages can't be retried before housekeeping has run...
                     current_sleep = 60
                 else:
@@ -621,7 +618,7 @@ def run(self):
                                                 self.o.messageRateMax):
                 stime = 1 + 2 * ((current_rate - self.o.messageRateMax) /
                                  self.o.messageRateMax)
-                logger.info(
+                logger.debug(
                     "current_rate/2 (%.2f) above messageRateMax(%.2f): throttling"
                     % (current_rate, self.o.messageRateMax))
             else:
@@ -1110,7 +1107,7 @@ def gather(self) -> None:
             return
 
         if len(self.worklist.incoming) > 0:
-            logger.info('ingesting %d postings into duplicate suppression cache' % len(self.worklist.incoming) )
+            logger.debug('ingesting %d postings into duplicate suppression cache' % len(self.worklist.incoming) )
             self.worklist.poll_catching_up = True
             return
         else:
@@ -1239,7 +1236,7 @@ def post(self,now) -> None:
                     mfn.write( f'\"{timestamp}\" : {metrics},\n')
 
             # removing old metrics files
-            logger.info( f"looking for old metrics for {self.o.metricsFilename}" )
+            logger.debug( f"looking for old metrics for {self.o.metricsFilename}" )
             old_metrics=sorted(glob.glob(self.o.metricsFilename+'.*'))[0:-self.o.logRotateCount]
             for o in old_metrics:
                 logger.info( f"removing old metrics file: {o} " )
@@ -1492,7 +1489,7 @@ def removeOneFile(self, path) -> bool:
             if os.path.isfile(path): os.unlink(path)
             if os.path.islink(path): os.unlink(path)
             if os.path.isdir(path): os.rmdir(path)
-            logger.info("removed %s" % path)
+            logger.debug("removed %s" % path)
         except:
             logger.error("could not remove %s." % path)
             logger.debug('Exception details: ', exc_info=True)
@@ -1505,7 +1502,6 @@ def renameOneItem(self, old, path) -> bool:
             for messages with an rename file operation, it is to rename a file.
         """
         ok = True
-        logger.info( f" pwd is {os.getcwd()}  " )
         if not os.path.exists(old):
             logger.info(
                 "old file %s not found, if destination (%s) missing, then fall back to copy"
@@ -1642,7 +1638,7 @@ def do_download(self) -> None:
 
             if not os.path.isdir(msg['new_dir']):
                 try:
-                    logger.info( f"missing destination directories, makedirs: {msg['new_dir']} " )
+                    logger.debug( f"missing destination directories, makedirs: {msg['new_dir']} " )
                     self.worklist.directories_ok.append(msg['new_dir'])
                     os.makedirs(msg['new_dir'], 0o775, True)
                 except Exception as ex:
@@ -2025,7 +2021,7 @@ def download(self, msg, options) -> bool:
                     remote_offset += msg['blocks']['manifest'][blkno]['size']
 
                 block_length=msg['blocks']['manifest'][msg['blocks']['number']]['size']
-                logger.info( f"offset calculation:  start={remote_offset} count={block_length}" )
+                logger.debug( f"offset calculation:  start={remote_offset} count={block_length}" )
 
             elif 'size' in msg:
                 block_length = msg['size']

sarracenia/flowcb/log.py

@@ -29,7 +29,7 @@ def __init__(self, options):
         self.o.add_option('logEvents', 'set',
                           ['after_accept', 'on_housekeeping'])
         self.o.add_option('logMessageDump', 'flag', False)
-        logger.info(f'{self.o.component} initialized with: logEvents: {self.o.logEvents},  logMessageDump: {self.o.logMessageDump}')
+        logger.debug(f'{self.o.component} initialized with: logEvents: {self.o.logEvents},  logMessageDump: {self.o.logMessageDump}')
         if self.o.component in ['sender']:
             self.action_verb = 'sent'
         elif self.o.component in ['subscribe', 'sarra' ]:

sarracenia/flowcb/nodupe/disk.py

@@ -56,8 +56,6 @@ def __init__(self, options):
 
         self.o.add_option( 'nodupe_ttl', 'duration', 0 ) 
 
-        logger.info('time_to_live=%d, ' % (self.o.nodupe_ttl))
-
         self.cache_dict = {}
         self.cache_file = None
         self.cache_hit = None
@@ -71,17 +69,17 @@ def __init__(self, options):
 
     def on_housekeeping(self):
 
-        logger.info("start (%d)" % len(self.cache_dict))
+        logger.debug("start with %d entries)" % len(self.cache_dict))
 
         count = self.count
         self.save()
 
         self.now = nowflt()
         new_count = self.count
 
-        logger.info(
-            "was %d, but since %5.2f sec, increased up to %d, now saved %d entries"
-            % (self.last_count, self.now - self.last_time, count, new_count))
+        if new_count > 0:
+            logger.info( "was %d, but since %5.2f sec, increased up to %d, now saved %d entries"
+                 % (self.last_count, self.now - self.last_time, count, new_count))
 
         self.last_time = self.now
         self.last_count = new_count

sarracenia/flowcb/post/message.py

@@ -63,9 +63,9 @@ def on_housekeeping(self):
     def on_start(self):
         if hasattr(self,'poster') and self.poster:
             self.poster.putSetup()
-        logger.info('starting')
+        logger.debug('starting')
 
     def on_stop(self):
         if hasattr(self,'poster') and self.poster:
             self.poster.close()
-        logger.info('closing')
+        logger.debug('closing')