changeset 8557:f80c566f5726

feat: improve store_trace_reason with extract parameter store_trace_reason() used embedded code to extract reason based on the location passed to the function. This change adds support for extract keyword that is a Python expression eval'ed when the underlying function/method is called. All callers now set the extract parameter. The prior embedded code has been removed from store_trace_reason(). Failure to eval the expression results in an roundup.logcontext error severity log. Also updated docs. Also replaced env['REQUEST_URI'] with env['PATH_INFO'] for web based entry points as REQUEST_URI isn't documented as a required key and some other front end (e.g. zope, cgi) might not supply this.
author John Rouillard <rouilj@ieee.org>
date Mon, 06 Apr 2026 22:10:23 -0400
parents dd0445649244
children 5fbf6451a782
files roundup/admin.py roundup/cgi/client.py roundup/cgi/wsgi_handler.py roundup/logcontext.py roundup/mailgw.py roundup/scripts/roundup_xmlrpc_server.py
diffstat 6 files changed, 83 insertions(+), 43 deletions(-) [+]
line wrap: on
line diff
--- a/roundup/admin.py	Mon Apr 06 01:30:55 2026 -0400
+++ b/roundup/admin.py	Mon Apr 06 22:10:23 2026 -0400
@@ -58,6 +58,18 @@
     from collections import UserDict
 
 
+def _safe_os_getlogin():
+    """Run os.getlogin handling OSError exception.
+
+       Used when calling @store_trace_reason to add username to string.
+    """
+    
+    try:
+        return os.getlogin()
+    except OSError:
+        return "--unknown--"
+
+
 class CommandDict(UserDict):
     """Simple dictionary that lets us do lookups using partial keys.
 
@@ -2363,7 +2375,10 @@
 
     @set_processName("roundup-admin")
     @gen_trace_id()
-    @store_trace_reason('admin')
+    @store_trace_reason("admin", extract=(
+        '"roundup-admin(%s): "' % _safe_os_getlogin() +
+        "'%s' % args[1][:2]"
+    ))
     def run_command(self, args):
         """Run a single command
         """
--- a/roundup/cgi/client.py	Mon Apr 06 01:30:55 2026 -0400
+++ b/roundup/cgi/client.py	Mon Apr 06 22:10:23 2026 -0400
@@ -436,7 +436,7 @@
     precompressed_mime_types = ["image/png", "image/jpeg"]
 
     @gen_trace_id()
-    @store_trace_reason('client')
+    @store_trace_reason('client', extract="args[3]['PATH_INFO']")
     def __init__(self, instance, request, env, form=None, translator=None):
         # re-seed the random number generator. Is this is an instance of
         # random.SystemRandom it has no effect.
@@ -588,7 +588,7 @@
         self.ngettext = translator.ngettext
 
     @gen_trace_id()
-    @store_trace_reason('client_main')
+    @store_trace_reason('client_main', extract="args[0].env['PATH_INFO']")
     def main(self):
         """ Wrap the real main in a try/finally so we always close off the db.
         """
--- a/roundup/cgi/wsgi_handler.py	Mon Apr 06 01:30:55 2026 -0400
+++ b/roundup/cgi/wsgi_handler.py	Mon Apr 06 22:10:23 2026 -0400
@@ -107,9 +107,11 @@
             "cache_tracker" not in self.feature_flags or
             self.feature_flags["cache_tracker"] is not False)
 
+    # Client entry point strips initial / from PATH_INFO so
+    # We need to do it here as well to prevent mismatch.
     @set_processName("wsgi_handler")
     @gen_trace_id()
-    @store_trace_reason("wsgi")
+    @store_trace_reason("wsgi", extract="args[1]['PATH_INFO'][1:]")
     def __call__(self, environ, start_response):
         """Initialize with `apache.Request` object"""
         request = RequestHandler(environ, start_response)
--- a/roundup/logcontext.py	Mon Apr 06 01:30:55 2026 -0400
+++ b/roundup/logcontext.py	Mon Apr 06 22:10:23 2026 -0400
@@ -2,12 +2,13 @@
 trace id for request, request source etc. to be logged.
 
 Trace id generator can use nanoid or uuid.uuid4 stdlib function.
-Nanoid is preferred if nanoid is installed using pip as nanoid is
-faster and generates a shorter id. If nanoid is installed in the
-tracker's lib subdirectory, it must be enabled using the tracker's
-interfaces.py by adding::
+Nanoid is preferred if nanoid is installed using pip. Nanoid is
+faster and generates a shorter id.
 
-   # if nanoid is installed in tracker's lib directory or
+If nanoid is installed in the tracker's lib subdirectory, it must be
+enabled using the tracker's interfaces.py by adding::
+
+   # if nanoid is installed in the tracker's lib directory and
    # if you want to change the length of the nanoid from 12
    # to 14 chars use:
    from functools import partial
@@ -16,20 +17,31 @@
    # change 14 to 12 to get the default nanoid size.
    roundup.logcontext.idgen=partial(generate, size=14)
 
-   # to force use of shortened uuid when nanoid is
-   # loaded by default
+   # If nanoid is instanned and you want to use use the shortened uuid
+   # add this to interfaces.py::
    import roundup.logcontext
    roundup.logcontext.idgen=roundup.logcontext.short_uuid
 
+If you are wrapping a staticmethod, you need to include staticmethod
+before the calls to gen_trace_id or store_trace_reason when wrapping a
+static method. If you don't the static method gets the self argument
+prepended which breaks the call. For example to wrap the 'serve'
+staticmethod from WhiteNoise::
+
+    WhiteNoise.serve = staticmethod(store_trace_reason(
+             extract="'whitenoise ' + args[1]['REQUEST_URI']")(
+             gen_trace_id()(WhiteNoise.serve)))
+
 """
 import contextvars
 import functools
 import logging
 import os
 import uuid
+from typing import Callable
 
 
-def short_uuid():
+def short_uuid() -> str:
     """Encode a UUID integer in a shorter form for display.
 
        A uuid is long. Make a shorter version that takes less room
@@ -51,7 +63,7 @@
     # with 1000 nanoid's/sec to generate a collision with 1%
     # probability. That's 100 users sec continously. These id's
     # are used to link logging messages/traces that are all done
-    # in a few seconds. Collisions ae unlikely to happen in the
+    # in a few seconds. Collisions are unlikely to happen in the
     # same time period leading to confusion.
     #
     # nanoid is faster than shortened uuids.
@@ -59,7 +71,7 @@
     # 1,000,000 generate(size=21) timeit.timeit at 33.7 seconds
 
     #: Variable used for setting the id generator.
-    idgen = functools.partial(generate, size=12)
+    idgen: Callable = functools.partial(generate, size=12)
 except ImportError:
     # 1,000,000 of short_uuid() timeit.timeit at 54.1 seconds
     idgen = short_uuid  #: :meta hide-value:
@@ -103,7 +115,7 @@
 # contactvars.copy_context().items() returns nothing if set has
 # not been called on a context var. I need the contextvar names
 # even if they have not been set.
-ctx_vars = {}
+ctx_vars: dict[str, contextvars.ContextVar] = {}
 
 # set up sentinel values that will print a suitable error value
 # and the context vars they are associated with.
@@ -121,7 +133,7 @@
                                                   default=_SENTINEL_REASON)
 
 
-def gen_trace_id():
+def gen_trace_id() -> Callable:
     """Decorator to generate a trace id (nanoid or encoded uuid4) as contextvar
 
        The logging routine uses this to label every log line. All
@@ -189,21 +201,25 @@
     return decorator
 
 
-def store_trace_reason(location=None):
+def store_trace_reason(location="unset", extract=None):
     """Decorator finds and stores a reason trace was started in contextvar.
 
-       Record the url for a regular web triggered request.
+       Record the url path for a regular web triggered request.
        Record the message id for an email triggered request.
        Record a roundup-admin command/action for roundup-admin request.
 
-       Because the reason can be stored in different locations
-       depending on where this is called, it is called with a
-       location hint to activate the right extraction method.
+       (*) There are multiple entry points to the code. Some entry
+       points call through other entry points. As a result this can be
+       called multiple times in one request.  Because the reason can
+       be stored from multiple locations depending on where this is
+       called, it is called with a location hint to identify the
+       caller (faster than looking up the stack).
 
-       If the reason has already been stored (and it's not "missing",
-       it tries to extract it again and verifies it's the same as the
+       If a reason has already been stored (and it's not "missing", it
+       tries to extract it again and verifies it's the same as the
        stored reason. If it's not the same it logs an error. This
        safety check may be removed in a future version of Roundup.
+
     """
     def decorator(func):
         @functools.wraps(func)
@@ -222,25 +238,28 @@
             # if stored_reason is not _SENTINEL_REASON:
             #     return func(*args, **kwargs)
 
-            # use location to determine how to extract the reason
-            if location == "wsgi" and 'REQUEST_URI' in args[1]:
-                reason = args[1]['REQUEST_URI']
-            elif location == "client" and 'REQUEST_URI' in args[3]:
-                reason = args[3]['REQUEST_URI']
-            elif location == "mailgw":
-                reason = args[1].get_header('message-id', "no_message_id")
-            elif location == "admin":
+            if extract:
                 try:
-                    login = os.getlogin()
-                except OSError:
-                    login = "--unknown--"
-                reason = "roundup-admin(%s): %s" % (login, args[1][:2])
-            elif location.startswith("file://"):
+                    reason = eval(extract,
+                                  {"__builtin__": {}},
+                                  {"args": args, "kwargs": kwargs})
+
+                except (IndexError, KeyError, TypeError) as e:
+                    # extract usually looks something like:
+                    #      "args[1]['PATH_INFO']"
+                    # report bad index/key/type
+                    logger.error(
+                        "Eval of extract('%(extract)s')@%(loc)s caused %(e)s" %
+                        {"e": repr(e), "extract": extract, "loc": location}
+                    )
+
+                    # provide fallback hinting that it is an error
+                    reason = "error@call_location:%s" % location
+
+            else:
+                # if no extract, use location as reason
+                # e.g. file://some_roundup-script
                 reason = location
-            elif location == "client_main" and 'REQUEST_URI' in args[0].env:
-                reason = args[0].env['REQUEST_URI']
-            elif location == "xmlrpc-server":
-                reason = args[0].path
 
             if reason is None:
                 pass
@@ -249,7 +268,9 @@
                 prev_trace_reason = trace_reason.set(reason)
             elif reason != stored_reason:   # SANITY CHECK
                 # Throw an error we have mismatched REASON's which
-                # should never happen.
+                # should never happen. It can happen if multiple
+                # functions are decorated and they don't agree on
+                # what the reason should be. see (*) above.
                 logger.error("Mismatched REASON's: stored: %s, new: %s at %s",
                              stored_reason, reason, location)
 
--- a/roundup/mailgw.py	Mon Apr 06 01:30:55 2026 -0400
+++ b/roundup/mailgw.py	Mon Apr 06 22:10:23 2026 -0400
@@ -1648,7 +1648,9 @@
                                                             RoundupMessage))
 
     @gen_trace_id()
-    @store_trace_reason("mailgw")
+    @store_trace_reason("mailgw",
+                    extract="args[1].get_header('message-id', 'no_message_id')"
+    )
     def handle_Message(self, message):
         """Handle an RFC822 Message
 
--- a/roundup/scripts/roundup_xmlrpc_server.py	Mon Apr 06 01:30:55 2026 -0400
+++ b/roundup/scripts/roundup_xmlrpc_server.py	Mon Apr 06 22:10:23 2026 -0400
@@ -89,7 +89,7 @@
         return db
 
     @gen_trace_id()
-    @store_trace_url("xmlrpc-server")
+    @store_trace_url("xmlrpc-server", extract="args[0].path")
     def do_POST(self):
         """Extract username and password from authorization header."""
 

Roundup Issue Tracker: http://roundup-tracker.org/