Refactor logging for efficiency, add fifo, context printing in text mode

.circleci/config.yml

@@ -611,6 +611,7 @@ workflows:
             branches:
               only:
                 - master
+                - visi-link-errinfo
 
       - build_docker_tag:
           requires:

synapse/axon.py

@@ -895,14 +895,15 @@ async def _axonHealth(self, health):
         health.update('axon', 'nominal', '', data=await self.metrics())
 
     async def _migrateAxonMetrics(self):
-        logger.warning('migrating Axon metrics data out of hive')
+        extra = self.getLogExtra()
+        logger.warning('Migrating Axon metrics data out of hive.', extra=extra)
 
         async with await self.hive.open(('axon', 'metrics')) as hivenode:
             axonmetrics = await hivenode.dict()
             self.axonmetrics.set('size:bytes', axonmetrics.get('size:bytes', 0))
             self.axonmetrics.set('file:count', axonmetrics.get('file:count', 0))
 
-        logger.warning('...Axon metrics migration complete!')
+        logger.warning('...Axon metrics migration complete!', extra=extra)
 
     async def _initBlobStor(self):
 
@@ -925,7 +926,8 @@ async def _initBlobStor(self):
 
     async def _setStorVers01(self):
 
-        logger.warning('Updating Axon storage version (adding offset index). This may take a while.')
+        extra = self.getLogExtra()
+        logger.warning('Updating Axon storage version (adding offset index). This may take a while.', extra=extra)
 
         offs = 0
         cursha = b''
@@ -1067,7 +1069,7 @@ async def get(self, sha256, offs=None, size=None):
         fsize = await self._reqHas(sha256)
 
         fhash = s_common.ehex(sha256)
-        logger.debug(f'Getting blob [{fhash}].', extra=await self.getLogExtra(sha256=fhash))
+        logger.debug('axon.get()', extra=self.getLogExtra(sha256=fhash))
 
         if offs is not None or size is not None:
 
@@ -1203,7 +1205,7 @@ async def hashset(self, sha256):
         await self._reqHas(sha256)
 
         fhash = s_common.ehex(sha256)
-        logger.debug(f'Getting blob [{fhash}].', extra=await self.getLogExtra(sha256=fhash))
+        logger.debug('axon.hashset()', extra=self.getLogExtra(sha256=fhash))
 
         hashset = s_hashset.HashSet()
 
@@ -1251,7 +1253,7 @@ async def _populate(self, sha256, genr, size):
                 return int.from_bytes(byts, 'big')
 
             fhash = s_common.ehex(sha256)
-            logger.debug(f'Saving blob [{fhash}].', extra=await self.getLogExtra(sha256=fhash))
+            logger.debug('axon.save()', extra=self.getLogExtra(sha256=fhash))
 
             size = await self._saveFileGenr(sha256, genr, size)
 
@@ -1378,7 +1380,7 @@ async def _axonFileDel(self, sha256):
                 return False
 
             fhash = s_common.ehex(sha256)
-            logger.debug(f'Deleting blob [{fhash}].', extra=await self.getLogExtra(sha256=fhash))
+            logger.debug('axon.del()', extra=self.getLogExtra(sha256=fhash))
 
             size = int.from_bytes(byts, 'big')
             self.axonmetrics.inc('file:count', valu=-1)
@@ -1447,7 +1449,7 @@ async def readlines(self, sha256, errors='ignore'):
             todo = s_common.todo(_spawn_readlines, sock00, errors=errors)
             async with await s_base.Base.anit() as scope:
 
-                scope.schedCoro(s_coro.spawn(todo, log_conf=await self._getSpawnLogConf()))
+                scope.schedCoro(s_coro.spawn(todo, logconf=self.getLogConf()))
                 feedtask = scope.schedCoro(self._sha256ToLink(sha256, link00))
 
                 while not self.isfini:
@@ -1481,7 +1483,7 @@ async def csvrows(self, sha256, dialect='excel', errors='ignore', **fmtparams):
             todo = s_common.todo(_spawn_readrows, sock00, dialect, fmtparams, errors=errors)
             async with await s_base.Base.anit() as scope:
 
-                scope.schedCoro(s_coro.spawn(todo, log_conf=await self._getSpawnLogConf()))
+                scope.schedCoro(s_coro.spawn(todo, logconf=self.getLogConf()))
                 feedtask = scope.schedCoro(self._sha256ToLink(sha256, link00))
 
                 while not self.isfini:
@@ -1503,17 +1505,20 @@ async def csvrows(self, sha256, dialect='excel', errors='ignore', **fmtparams):
                 await feedtask
 
     async def jsonlines(self, sha256, errors='ignore'):
+
         async for line in self.readlines(sha256, errors=errors):
+
             line = line.strip()
             if not line:
                 continue
 
             try:
                 yield s_json.loads(line)
             except s_exc.BadJsonText as e:
-                logger.exception(f'Bad json line encountered for {sha256}')
-                raise s_exc.BadJsonText(mesg=f'Bad json line encountered while processing {sha256}, ({e})',
-                                        sha256=sha256) from None
+                extra = self.getLogExtra(line=line, sha256=sha256, err=str(e))
+                logger.warning('Bad JSON line encountered.', extra=extra)
+                mesg = f'Bad JSON line while processing {sha256}: {e}'
+                raise s_exc.BadJsonText(mesg=mesg, sha256=sha256) from None
 
     async def unpack(self, sha256, fmt, offs=0):
         '''
@@ -1664,7 +1669,8 @@ async def postfiles(self, fields, url, params=None, headers=None, method='POST',
                     return info
 
             except Exception as e:
-                logger.exception(f'Error POSTing files to [{s_urlhelp.sanitizeUrl(url)}]')
+                extra = self.getLogExtra(url=s_urlhelp.sanitizeUrl(url))
+                logger.exception('Axon file HTTP POST request failed.', extra=extra)
                 err = s_common.err(e)
                 errmsg = err[1].get('mesg')
                 if errmsg:
@@ -1711,7 +1717,8 @@ async def wput(self, sha256, url, params=None, headers=None, method='PUT', ssl=T
                     return info
 
             except Exception as e:
-                logger.exception(f'Error streaming [{sha256}] to [{s_urlhelp.sanitizeUrl(url)}]')
+                extra = self.getLogExtra(sha256=sha256, url=s_urlhelp.sanitizeUrl(url))
+                logger.exception('Axon file HTTP PUT request failed.', extra=extra)
                 err = s_common.err(e)
                 errmsg = err[1].get('mesg')
                 if errmsg:
@@ -1814,7 +1821,8 @@ async def wget(self, url, params=None, headers=None, json=None, body=None, metho
         Returns:
             dict: An information dictionary containing the results of the request.
         '''
-        logger.debug(f'Wget called for [{url}].', extra=await self.getLogExtra(url=s_urlhelp.sanitizeUrl(url)))
+        extra = self.getLogExtra(url=s_urlhelp.sanitizeUrl(url))
+        logger.debug('axon.wget()', extra=extra)
 
         ssl = self.getCachedSslCtx(opts=ssl_opts, verify=ssl)
 
@@ -1848,7 +1856,8 @@ async def wget(self, url, params=None, headers=None, json=None, body=None, metho
                 raise
 
             except Exception as e:
-                logger.exception(f'Failed to wget {s_urlhelp.sanitizeUrl(url)}')
+                extra = self.getLogExtra(url=s_urlhelp.sanitizeUrl(url))
+                logger.exception('Axon failed to retrieve URL.', extra=extra)
                 err = s_common.err(e)
                 errmsg = err[1].get('mesg')
                 if errmsg:

synapse/common.py

@@ -37,7 +37,6 @@
 import synapse.exc as s_exc
 import synapse.lib.const as s_const
 import synapse.lib.msgpack as s_msgpack
-import synapse.lib.structlog as s_structlog
 
 import synapse.vendor.cpython.lib.ipaddress as ipaddress
 import synapse.vendor.cpython.lib.http.cookies as v_cookies
@@ -763,83 +762,6 @@ def makedirs(path, mode=0o777):
 def iterzip(*args, fillvalue=None):
     return itertools.zip_longest(*args, fillvalue=fillvalue)
 
-def _getLogConfFromEnv(defval=None, structlog=None, datefmt=None):
-    if structlog:
-        structlog = 'true'
-    else:
-        structlog = 'false'
-    defval = os.getenv('SYN_LOG_LEVEL', defval)
-    datefmt = os.getenv('SYN_LOG_DATEFORMAT', datefmt)
-    structlog = envbool('SYN_LOG_STRUCT', structlog)
-    ret = {'defval': defval, 'structlog': structlog, 'datefmt': datefmt}
-    return ret
-
-def normLogLevel(valu):
-    '''
-    Norm a log level value to a integer.
-
-    Args:
-        valu: The value to norm ( a string or integer ).
-
-    Returns:
-        int: A valid Logging log level.
-    '''
-    if isinstance(valu, int):
-        if valu not in s_const.LOG_LEVEL_INVERSE_CHOICES:
-            raise s_exc.BadArg(mesg=f'Invalid log level provided: {valu}', valu=valu)
-        return valu
-    if isinstance(valu, str):
-        valu = valu.strip()
-        try:
-            valu = int(valu)
-        except ValueError:
-            valu = valu.upper()
-            ret = s_const.LOG_LEVEL_CHOICES.get(valu)
-            if ret is None:
-                raise s_exc.BadArg(mesg=f'Invalid log level provided: {valu}', valu=valu) from None
-            return ret
-        else:
-            return normLogLevel(valu)
-    raise s_exc.BadArg(mesg=f'Unknown log level type: {type(valu)} {valu}', valu=valu)
-
-def setlogging(mlogger, defval=None, structlog=None, log_setup=True, datefmt=None):
-    '''
-    Configure synapse logging.
-
-    Args:
-        mlogger (logging.Logger): Reference to a logging.Logger()
-        defval (str): Default log level. May be an integer.
-        structlog (bool): Enabled structured (jsonl) logging output.
-        datefmt (str): Optional strftime format string.
-
-    Notes:
-        This calls logging.basicConfig and should only be called once per process.
-
-    Returns:
-        None
-    '''
-    ret = _getLogConfFromEnv(defval, structlog, datefmt)
-
-    datefmt = ret.get('datefmt')
-    log_level = ret.get('defval')
-    log_struct = ret.get('structlog')
-
-    if log_level:  # pragma: no cover
-
-        log_level = normLogLevel(log_level)
-
-        if log_struct:
-            handler = logging.StreamHandler()
-            formatter = s_structlog.JsonFormatter(datefmt=datefmt)
-            handler.setFormatter(formatter)
-            logging.basicConfig(level=log_level, handlers=(handler,))
-        else:
-            logging.basicConfig(level=log_level, format=s_const.LOG_FORMAT, datefmt=datefmt)
-        if log_setup:
-            mlogger.info('log level set to %s', s_const.LOG_LEVEL_INVERSE_CHOICES.get(log_level))
-
-    return ret
-
 syndir_default = '~/.syn'
 syndir = os.getenv('SYN_DIR')
 if syndir is None: