Logging updates & feedback from testing

.circleci/config.yml

@@ -626,6 +626,7 @@ workflows:
             branches:
               only:
                 - master
+                - visi-logging-epiphyte-fb
 
       - build_docker_tag:
           requires:

changes/7ef2889edb0c2bfb214207b97f0394db.yaml

@@ -0,0 +1,7 @@
+---
+desc: Deprecated ``synapse.lib.structlog.JsonFormatter``.  It will be removed after
+  April 1st, 2026.
+desc:literal: false
+prs: []
+type: deprecation
+...

docs/synapse/devopsguide.rst

@@ -346,46 +346,77 @@ These structured logs are designed to be easy to ingest into third party log col
 message, level, time, and metadata about where the log message came from::
 
     {
-      "message": "log level set to INFO",
+      "ahaservice": "00.cortex.synapse",
+      "message": "Executing storm query {[inet:asn=1234]} as [someUsername]",
       "logger": {
-        "name": "synapse.lib.cell",
+        "name": "synapse.storm",
+        "func": "_logStormQuery",
         "process": "MainProcess",
-        "filename": "common.py",
-        "func": "setlogging"
+        "thread": "MainThread"
       },
       "level": "INFO",
-      "time": "2021-06-28 15:47:54,825"
+      "time": "2026-02-13 10:38:24,545",
+      "user": "a8b94560fd9b6e1e38245a6f7d659106",
+      "username": "root",
+      "params": {  # Param
+        "mode": "storm",
+        "view": "715a5c9ae37e4045795ea3f3cabb44fb",
+        "text": "[inet:asn=1234]",
+        "username": "someUsername",
+        "user": "e3532bc88fa66afb592e6a1474a98675",
+        "hash": "ef94e89eb3bc309a40242876f6c5f296"
+      }
     }
 
+The ``user`` and ``username`` fields at the top level of a log correspond to the currently active / authorized API user
+which has caused a log event to occur. These may differ from the user associated with the event. That information would
+normally be embedded in the ``params`` key.  The ``ahaservice`` key, if present, indicates the service that is
+associated with the log message.
+
 When exceptions are logged with structured logging, we capture additional information about the exception, including the
-entire traceback. In the event that the error is a Synapse Err class, we also capture additional metadata which was
-attached to the error. In the following example, we also have the query text, username and user iden available in the
-log message pretty-printed log message::
+traceback as structured data. In the event that the error is a Synapse Err class, we also capture additional metadata
+which was attached to the error. In the following example, we also have the query text, username and user iden available
+in the pretty-printed log message. The ``key=valu`` data that was raised by the user is also included in the
+``error.info.`` dictionary. Cause and Context information may be present, corresponding to the Python ``__cause__`` and
+``__context__`` attributes on Exception classes.::
 
     {
-      "message": "Error during storm execution for { || }",
+      "ahaservice": "00.cortex.synapse",
+      "message": "Error during storm execution for { $lib.raise(Newp, 'ruh roh', key=valu) }",
       "logger": {
         "name": "synapse.lib.view",
+        "func": "runStorm",
         "process": "MainProcess",
-        "filename": "view.py",
-        "func": "runStorm"
+        "thread": "MainThread"
       },
       "level": "ERROR",
-      "time": "2021-06-28 15:49:34,401",
-      "err": {
-        "efile": "coro.py",
-        "eline": 233,
-        "esrc": "return await asyncio.get_running_loop().run_in_executor(forkpool, _runtodo, todo)",
-        "ename": "forked",
-        "at": 1,
-        "text": "||",
-        "mesg": "No terminal defined for '|' at line 1 col 2.  Expecting one of: #, $, (, *, + or -, -(, -+>, -->, ->, :, <(, <+-, <-, <--, [, break, command name, continue, fini, for, function, if, init, property name, return, switch, while, whitespace or comment, yield, {",
-        "etb": ".... long traceback ...",
-        "errname": "BadSyntax"
-      },
-      "text": "||",
+      "time": "2026-02-13 11:24:06,853",
+      "user": "e889d295b19fd5c12f861cd6fe564aa8",
       "username": "root",
-      "user": "3189065f95d3ab0a6904e604260c0be2"
+      "error": {
+        "code": "StormRaise",
+        "traceback": [
+          ... list of traceback frames ...
+          [
+            "/home/epiphyte/PycharmProjects/synapse/synapse/lib/stormtypes.py",
+            1751,
+            "_raise",
+            "raise s_exc.StormRaise(**info)"
+          ]
+        ],
+        "info": {
+          "key": "valu",
+          "errname": "Newp",
+          ... additional error information ...
+          }
+        },
+        "mesg": "ruh roh"
+      },
+      "params": {
+        "text": "$lib.raise(Newp, 'ruh roh', key=valu)",
+        "user": "e3532bc88fa66afb592e6a1474a98675",
+        "username": "someUsername"
+      }
     }
 
 Custom date formatting strings can also be provided by setting the ``SYN_LOG_DATEFORMAT`` string. This is expected to be a

synapse/common.py

@@ -41,7 +41,6 @@
 import synapse.lib.const as s_const
 import synapse.lib.logging as s_logging
 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

synapse/cortex.py

@@ -1058,15 +1058,15 @@ async def initServiceStorage(self):
 
             mesg = f'User {useriden} ({user.name}) has a rule on the "cortex" authgate. This authgate is not used ' \
                    f'for permission checks and will be removed in Synapse v3.0.0.'
-            logger.warning(mesg, extra=self.getLogExtra(user=useriden, username=user.name))
+            logger.warning(mesg)
         for roleiden in ag.gateroles.keys():
             role = self.auth.role(roleiden)
             if role is None:
                 continue
 
             mesg = f'Role {roleiden} ({role.name}) has a rule on the "cortex" authgate. This authgate is not used ' \
                    f'for permission checks and will be removed in Synapse v3.0.0.'
-            logger.warning(mesg, extra=self.getLogExtra(role=roleiden, rolename=role.name))
+            logger.warning(mesg)
 
         self._initVaults()
 
@@ -6449,8 +6449,7 @@ async def _getStormEval(self, text):
         try:
             astvalu = copy.deepcopy(await s_parser.evalcache.aget(text))
         except s_exc.FatalErr: # pragma: no cover
-            extra = self.getLogExtra(text=text)
-            logger.exception(f'Fatal error while parsing [{text}]', extra=extra)
+            logger.exception(f'Fatal error while parsing [{text}]', extra=self.getLogExtra(text=text))
             await self.fini()
             raise
         astvalu.init(self)
@@ -6460,8 +6459,7 @@ async def _getStormQuery(self, args):
         try:
             query = copy.deepcopy(await s_parser.querycache.aget(args))
         except s_exc.FatalErr: # pragma: no cover
-            extra = self.getLogExtra(text=args[0])
-            logger.exception(f'Fatal error while parsing [{args}]', extra=extra)
+            logger.exception(f'Fatal error while parsing [{args}]', extra=self.getLogExtra(text=args[0]))
             await self.fini()
             raise
         query.init(self)
@@ -6511,12 +6509,9 @@ def _logStormQuery(self, text, user, info=None):
             if info is None:
                 info = {}
             info['text'] = text
-            info['username'] = user.name
-            info['user'] = user.iden
             info['hash'] = s_storm.queryhash(text)
-            extra = s_logging.getLogExtra(**info)
             stormlogger.log(self.stormloglvl, 'Executing storm query {%s} as [%s]', text, user.name,
-                            extra=extra)
+                            extra=self.getLogExtra(**info))
 
     async def getNodeByNdef(self, ndef, view=None):
         '''

synapse/datamodel.py

@@ -16,6 +16,7 @@
 import synapse.lib.types as s_types
 import synapse.lib.dyndeps as s_dyndeps
 import synapse.lib.grammar as s_grammar
+import synapse.lib.logging as s_logging
 import synapse.lib.msgpack as s_msgpack
 
 logger = logging.getLogger(__name__)
@@ -948,7 +949,6 @@ def addType(self, typename, basename, typeopts, typeinfo, checks=True):
     def _checkTypeDef(self, typ):
         if 'comp' in typ.info.get('bases', ()):
             for fname, ftypename in typ.opts.get('fields', ()):
-                extra = {'synapse': {'type': typ.name, 'field': fname}}
 
                 if isinstance(ftypename, (list, tuple)):
                     ftypename = ftypename[0]
@@ -957,7 +957,7 @@ def _checkTypeDef(self, typ):
                     ftype = typ.tcache[fname]
                 except s_exc.BadTypeDef:
                     mesg = f'The {typ.name} field {fname} is declared as a type ({ftypename}) that does not exist.'
-                    logger.warning(mesg, extra=extra)
+                    logger.warning(mesg, s_logging.getLogExtra(type=typ.name, field=fname))
                     continue
 
                 # We're only interested in extended model comp types
@@ -966,12 +966,11 @@ def _checkTypeDef(self, typ):
 
                 if ftype.ismutable:
                     mesg = f'Comp types with mutable fields ({typ.name}:{fname}) are deprecated and will be removed in 3.0.0.'
-                    logger.warning(mesg, extra=extra)
+                    logger.warning(mesg, s_logging.getLogExtra(type=typ.name, field=fname))
 
                 if ftype.deprecated:
                     mesg = f'The type {typ.name} field {fname} uses a deprecated type {ftype.name}.'
-                    extra['synapse']['field:type'] = ftype.name
-                    logger.warning(mesg, extra=extra)
+                    logger.warning(mesg, s_logging.getLogExtra(type=typ.name, field=fname, field_type=ftype.name))
 
     def addForm(self, formname, forminfo, propdefs, checks=True):
 

synapse/lib/agenda.py

@@ -14,6 +14,7 @@
 
 import synapse.lib.base as s_base
 import synapse.lib.coro as s_coro
+import synapse.lib.scope as s_scope
 import synapse.lib.logging as s_logging
 
 # Agenda: manages running one-shot and periodic tasks in the future ("appointments")
@@ -832,22 +833,18 @@ async def runloop(self):
                 if appt.isrunning:  # pragma: no cover
                     mesg = f'Appointment {appt.iden} {appt.name} is still running from previous time when scheduled' \
                            f' to run. Skipping.'
-                    logger.warning(mesg,
-                                   extra={'synapse': {'iden': appt.iden, 'name': appt.name}})
+                    logger.warning(mesg, extra=self.core.getLogExtra(iden=appt.iden, name=appt.name))
                 else:
                     try:
                         await self._execute(appt)
                     except Exception as e:
-                        extra = {'iden': appt.iden, 'name': appt.name, 'user': appt.creator, 'view': appt.view}
-                        user = self.core.auth.user(appt.creator)
-                        if user is not None:
-                            extra['username'] = user.name
+                        extra = {'iden': appt.iden, 'name': appt.name, 'view': appt.view}
                         if isinstance(e, s_exc.SynErr):
                             mesg = e.get('mesg', str(e))
                         else:  # pragma: no cover
                             mesg = str(e)
                         logger.exception(f'Agenda error running appointment {appt.iden} {appt.name}: {mesg}',
-                                         extra={'synapse': extra})
+                                         extra=self.core.getLogExtra(**extra))
                         await self._markfailed(appt, f'error: {e}')
 
     async def _execute(self, appt):
@@ -857,30 +854,29 @@ async def _execute(self, appt):
         user = self.core.auth.user(appt.creator)
         if user is None:
             logger.warning(f'Unknown user {appt.creator} in stored appointment {appt.iden} {appt.name}',
-                           extra={'synapse': {'iden': appt.iden, 'name': appt.name, 'user': appt.creator}})
+                           extra=self.core.getLogExtra(iden=appt.iden, name=appt.name, user=appt.creator))
             await self._markfailed(appt, 'unknown user')
             return
 
         locked = user.info.get('locked')
         if locked:
             logger.warning(f'Cron {appt.iden} {appt.name} failed because creator {user.name} is locked',
-                           extra={'synapse': {'iden': appt.iden, 'name': appt.name, 'user': appt.creator,
-                                              'username': user.name}})
+                           extra=self.core.getLogExtra(iden=appt.iden, name=appt.name))
             await self._markfailed(appt, 'locked user')
             return
 
         view = self.core.getView(iden=appt.view, user=user)
         if view is None:
             logger.warning(f'Unknown view {appt.view} in stored appointment {appt.iden} {appt.name}',
-                           extra={'synapse': {'iden': appt.iden, 'name': appt.name, 'user': appt.creator,
-                                              'username': user.name, 'view': appt.view}})
+                           extra=self.core.getLogExtra(iden=appt.iden, name=appt.name, view=appt.view))
             await self._markfailed(appt, 'unknown view')
             return
 
         info = {'iden': appt.iden, 'query': appt.query, 'view': view.iden}
 
         coro = self._runJob(user, appt)
         task = self.core.runActiveTask(coro)
+        task._syn_scope['user'] = user
 
         appt.task = await self.core.boss.promotetask(task, f'Cron {appt.iden}', user, info=info)
         async def fini():
@@ -912,8 +908,7 @@ async def _runJob(self, user, appt):
         await self.core.addCronEdits(appt.iden, edits)
 
         logger.info(f'Agenda executing for iden={appt.iden}, name={appt.name} user={user.name}, view={appt.view}, query={appt.query}',
-                    extra={'synapse': {'iden': appt.iden, 'name': appt.name, 'user': user.iden, 'text': appt.query,
-                                       'username': user.name, 'view': appt.view}})
+                    extra=self.core.getLogExtra(iden=appt.iden, name=appt.name, text=appt.query, view=appt.iden))
         starttime = self._getNowTick()
 
         success = False
@@ -940,8 +935,10 @@ async def _runJob(self, user, appt):
 
                 elif mesg[0] == 'warn' and loglevel <= logging.WARNING:
                     text = mesg[1].get('mesg', '<missing message>')
-                    extra = self.core.getLogExtra(cron=appt.iden, **mesg[1])
-                    logger.warning(f'Cron job {appt.iden} issued warning: {text}', extra=extra)
+                    _params = mesg[1]
+                    _params['iden'] = appt.iden
+                    logger.warning(f'Cron job {appt.iden} issued warning: {text}',
+                                   extra=self.core.getLogExtra(**_params))
 
                 elif mesg[0] == 'err':
                     excname, errinfo = mesg[1]
@@ -957,7 +954,7 @@ async def _runJob(self, user, appt):
         except Exception as e:
             result = f'raised exception {e}'
             logger.exception(f'Agenda job {appt.iden} {appt.name} raised exception',
-                             extra={'synapse': {'iden': appt.iden, 'name': appt.name}}
+                             extra=self.core.getLogExtra(iden=appt.iden, name=appt.name),
                              )
         else:
             success = True
@@ -981,8 +978,7 @@ async def _runJob(self, user, appt):
                    f'took {took:.3f}s'
             if not self.core.isactive:
                 mesg = mesg + ' Agenda status will not be saved since the Cortex is no longer the leader.'
-            logger.info(mesg, extra={'synapse': {'iden': appt.iden, 'name': appt.name, 'user': user.iden,
-                                                 'result': result, 'username': user.name, 'took': took}})
+            logger.info(mesg, extra=self.core.getLogExtra(iden=appt.iden, name=appt.name, result=result, took=took))
             edits = {
                 'lastfinishtime': finishtime,
                 'isrunning': False,

synapse/lib/auth.py

@@ -1458,17 +1458,15 @@ async def tryPasswd(self, passwd, nexs=True, enforce_policy=True):
                 if expires >= s_common.now():
                     if await s_passwd.checkShadowV2(passwd=passwd, shadow=shadow):
                         await self.auth.setUserInfo(self.iden, 'onepass', None)
-                        logger.debug(f'Used one time password for {self.name}',
-                                     extra={'synapse': {'user': self.iden, 'username': self.name}})
+                        logger.debug(f'Used one time password for {self.name}')
                         return True
             else:
                 # Backwards compatible password handling
                 expires, params, hashed = onepass
                 if expires >= s_common.now():
                     if s_common.guid((params, passwd)) == hashed:
                         await self.auth.setUserInfo(self.iden, 'onepass', None)
-                        logger.debug(f'Used one time password for {self.name}',
-                                     extra={'synapse': {'user': self.iden, 'username': self.name}})
+                        logger.debug(f'Used one time password for {self.name}')
                         return True
 
         shadow = self.info.get('passwd')
@@ -1493,15 +1491,15 @@ async def tryPasswd(self, passwd, nexs=True, enforce_policy=True):
 
                         if self.iden == self.auth.rootuser.iden:
                             mesg = f'User {self.name} has exceeded the number of allowed password attempts ({valu + 1}),. Cannot lock {self.name} user.'
-                            extra = {'synapse': {'target_user': self.iden, 'target_username': self.name, }}
-                            logger.error(mesg, extra=extra)
+                            logger.error(mesg, extra=self.auth.nexsroot.cell.getLogExtra(target_user=self.iden, target_username=self.name))
                             return False
 
                         await self.auth.nexsroot.cell.setUserLocked(self.iden, True)
 
-                        mesg = f'User {self.name} has exceeded the number of allowed password attempts ({valu + 1}), locking their account.'
-                        extra = {'synapse': {'target_user': self.iden, 'target_username': self.name, 'status': 'MODIFY'}}
-                        logger.warning(mesg, extra=extra)
+                        mesg = f'User {self.name} has exceeded the number of allowed password attempts ({valu + 1}), locked their account.'
+                        logger.warning(mesg, extra=self.auth.nexsroot.cell.getLogExtra(target_user=self.iden,
+                                                                                      target_username=self.name,
+                                                                                      status='MODIFY'))
 
                     return False
 
@@ -1510,8 +1508,7 @@ async def tryPasswd(self, passwd, nexs=True, enforce_policy=True):
         # Backwards compatible password handling
         salt, hashed = shadow
         if s_common.guid((salt, passwd)) == hashed:
-            logger.debug(f'Migrating password to shadowv2 format for user {self.name}',
-                         extra={'synapse': {'user': self.iden, 'username': self.name}})
+            logger.debug(f'Migrating password to shadowv2 format for user {self.name}')
             # Update user to new password hashing scheme. We cannot enforce policy
             # when migrating an existing password.
             await self.setPasswd(passwd=passwd, nexs=nexs, enforce_policy=False)

synapse/lib/base.py

@@ -18,6 +18,7 @@
 
 import synapse.lib.coro as s_coro
 import synapse.lib.scope as s_scope
+import synapse.lib.logging as s_logging
 
 logger = logging.getLogger(__name__)
 
@@ -599,6 +600,9 @@ async def main(self, timeout=BASE_MAIN_BG_TASK_TIMEOUT): # pragma: no cover
         '''
         await self.addSignalHandlers()
         await self.waitfini()
+        # shutdown logging to allow it to drain any queued messages it has, swapping in a stream handler,
+        # and then cancellling the task so we do not have to await the pump task in bg tasks.
+        await s_logging.shutdown()
         await s_coro.await_bg_tasks(timeout)
 
     def waiter(self, count, *names, timeout=None):