changeset 8487:b09ef85f0da6

feat: add nanoid pkg trace_id gen and decorator for setting processName nanoid is a shorter unique id generator and faster than uuid. I truncate nanoid id's to 12 chars to make it more readable. Also added decorator to allow setting the default processName definition in the logging module. admin.py and wsgi_handler now set processName. configuration.py knows how to overide the processName if set to the default MainProcess. Updated install docs to add nanoid as optional, how to switch to different trace_id output. pydoc generated docs include logcontext module and are referenced from admin.py.
author John Rouillard <rouilj@ieee.org>
date Mon, 08 Dec 2025 00:23:14 -0500
parents ed4ef394d5d6
children 7142740e6547
files CHANGES.txt doc/admin_guide.txt doc/installation.txt doc/pydoc.txt roundup/admin.py roundup/cgi/wsgi_handler.py roundup/configuration.py roundup/logcontext.py
diffstat 8 files changed, 141 insertions(+), 33 deletions(-) [+]
line wrap: on
line diff
--- a/CHANGES.txt	Sat Nov 15 16:59:24 2025 -0500
+++ b/CHANGES.txt	Mon Dec 08 00:23:14 2025 -0500
@@ -54,9 +54,10 @@
   logging format. (John Rouillard)
 - the default logging format template includes an identifier unique
   for a request. This identifier (trace_id) can be use to identify
-  logs for a specific transaction. Logging also supports a
-  trace_reason log token with the url for a web request. The logging
-  format can be changed in config.ini. (John Rouillard)
+  logs for a specific transaction. Will use nanoid if installed, uses
+  uuid.uuid4 otherwise. Logging also supports a trace_reason log token
+  with the url for a web request. The logging format can be changed in
+  config.ini. (John Rouillard)
 
 2025-07-13 2.5.0
 
--- a/doc/admin_guide.txt	Sat Nov 15 16:59:24 2025 -0500
+++ b/doc/admin_guide.txt	Mon Dec 08 00:23:14 2025 -0500
@@ -239,8 +239,8 @@
 ~~~~~~~~~~~~~~~~
 
 The trace_id provides a unique token (a UUID4 encoded to make it
-shorter) for each transaction in the database. It is unique to
-each thread or transaction. A transaction:
+shorter or a nanoid) for each transaction in the database. It is
+unique to each thread or transaction. A transaction:
 
   for the web interface is
       each web, rest or xmlrpc request
@@ -282,7 +282,11 @@
        for thing in things:
 	   process_one(thing)
       
-
+You can change the format of the trace_id if required using the
+tracker's interfaces.py file. See the :ref:`module docs for the
+logcontext module <logcontext_pydoc>` for details.
+
+	   
 Advanced Logging Setup
 ----------------------
 
--- a/doc/installation.txt	Sat Nov 15 16:59:24 2025 -0500
+++ b/doc/installation.txt	Mon Dec 08 00:23:14 2025 -0500
@@ -253,7 +253,11 @@
   version 2.0 of gpg from test.pypi.org. See the `gpg install
   directions in the upgrading document`_.
 
-
+nanoid
+  If nanoid_ is installed, it is used to generate short unique
+  ids to link all logging to a single request. If not installed,
+  uuid4's from the standard library are used.
+  
 jinja2
   To use the jinja2 template (may still be experimental, check out
   its TEMPLATE-INFO.txt file) you need
@@ -2432,6 +2436,7 @@
 .. _mod_python: https://github.com/grisha/mod_python
 .. _mod_wsgi: https://pypi.org/project/mod-wsgi/
 .. _MySQLdb: https://pypi.org/project/mysqlclient/
+.. _nanoid: https://pypi.org/project/nanoid/
 .. _Olson tz database: https://www.iana.org/time-zones
 .. _polib: https://polib.readthedocs.io
 .. _Psycopg2: https://www.psycopg.org/
--- a/doc/pydoc.txt	Sat Nov 15 16:59:24 2025 -0500
+++ b/doc/pydoc.txt	Mon Dec 08 00:23:14 2025 -0500
@@ -1,10 +1,14 @@
-================
-Pydocs from code
-================
+================================
+Embedded documentation from code
+================================
 
 .. contents::
    :local:
 
+The following are embedded documentation selected from the Roundup
+code base. You can see the same information using the ``help``
+function after importing the modules.
+
 Client class
 ============
 
@@ -40,3 +44,11 @@
 
 .. autoclass:: roundup.cgi.templating::TemplatingUtils
    :members:
+
+Logcontext Module
+=================
+.. _logcontext_pydoc:
+
+.. automodule:: roundup.logcontext
+   :members:
+   :exclude-members: SimpleSentinel
--- a/roundup/admin.py	Sat Nov 15 16:59:24 2025 -0500
+++ b/roundup/admin.py	Mon Dec 08 00:23:14 2025 -0500
@@ -49,7 +49,7 @@
 )
 from roundup.exceptions import UsageError
 from roundup.i18n import _, get_translation
-from roundup.logcontext import gen_trace_id, store_trace_reason
+from roundup.logcontext import gen_trace_id, set_processName, store_trace_reason
 
 try:
     from UserDict import UserDict
@@ -2355,6 +2355,7 @@
         print(function.__doc__)
         return 1
 
+    @set_processName("roundup-admin")
     @gen_trace_id()
     @store_trace_reason('admin')
     def run_command(self, args):
--- a/roundup/cgi/wsgi_handler.py	Sat Nov 15 16:59:24 2025 -0500
+++ b/roundup/cgi/wsgi_handler.py	Mon Dec 08 00:23:14 2025 -0500
@@ -13,7 +13,7 @@
 from roundup.anypy.strings import s2b
 from roundup.cgi import TranslationService
 from roundup.cgi.client import BinaryFieldStorage
-from roundup.logcontext import gen_trace_id, store_trace_reason
+from roundup.logcontext import gen_trace_id, set_processName, store_trace_reason
 
 BaseHTTPRequestHandler = http_.server.BaseHTTPRequestHandler
 DEFAULT_ERROR_MESSAGE = http_.server.DEFAULT_ERROR_MESSAGE
@@ -107,6 +107,7 @@
             "cache_tracker" not in self.feature_flags or
             self.feature_flags["cache_tracker"] is not False)
 
+    @set_processName("wsgi_handler")
     @gen_trace_id()
     @store_trace_reason("wsgi")
     def __call__(self, environ, start_response):
--- a/roundup/configuration.py	Sat Nov 15 16:59:24 2025 -0500
+++ b/roundup/configuration.py	Mon Dec 08 00:23:14 2025 -0500
@@ -2440,6 +2440,12 @@
         for name, value in get_context_info():
             if not hasattr(record, name):
                 setattr(record, name, value)
+                continue
+            if (name == "processName" and
+                isinstance(value, str) and
+                getattr(record, name) == "MainProcess"):
+                setattr(record, name, value)
+                    
         record.pct_char = "%"
         record.ROUNDUP_CONTEXT_FILTER_CALLED = True
 
--- a/roundup/logcontext.py	Sat Nov 15 16:59:24 2025 -0500
+++ b/roundup/logcontext.py	Mon Dec 08 00:23:14 2025 -0500
@@ -1,9 +1,70 @@
+"""Generate and store thread local logging context including unique
+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::
+
+   # if nanoid is installed in tracker's lib directory or
+   # if you want to change the length of the nanoid from 12
+   # to 14 chars use:
+   from functools import partial
+   from nanoid import generate
+   import roundup.logcontext
+   # 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
+   import roundup.logcontext
+   roundup.logcontext.idgen=roundup.logcontext.short_uuid
+
+"""
 import contextvars
 import functools
 import logging
 import os
 import uuid
 
+
+def short_uuid():
+    """Encode a UUID integer in a shorter form for display.
+
+       A uuid is long. Make a shorter version that takes less room
+       in a log line and is easier to store.
+    """
+    alphabet = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz1234567890"
+    result = ""
+    alphabet_len = len(alphabet)
+    uuid_int = uuid.uuid4().int
+    while uuid_int:
+        uuid_int, t = divmod(uuid_int, alphabet_len)
+        result += alphabet[t]
+    return result or "0"
+
+
+try:
+    from nanoid import generate
+    # With size=12 and the normal alphabet, it take ~4 months
+    # 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
+    # same time period leading to confusion.
+    #
+    # nanoid is faster than shortened uuids.
+    # 1,000,000 generate(size=12) timeit.timeit at 25.4 seconds
+    # 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)
+except ImportError:
+    # 1,000,000 of short_uuid() timeit.timeit at 54.1 seconds
+    idgen = short_uuid  #: :meta hide-value:
+
+
 logger = logging.getLogger("roundup.logcontext")
 
 
@@ -46,6 +107,11 @@
 
 # set up sentinel values that will print a suitable error value
 # and the context vars they are associated with.
+_SENTINEL_PROCESSNAME = SimpleSentinel("processName", None)
+ctx_vars['processName'] = contextvars.ContextVar("processName",
+                                                  default=_SENTINEL_PROCESSNAME)
+
+
 _SENTINEL_ID = SimpleSentinel("trace_id", "not set")
 ctx_vars['trace_id'] = contextvars.ContextVar("trace_id", default=_SENTINEL_ID)
 
@@ -55,23 +121,8 @@
                                                   default=_SENTINEL_REASON)
 
 
-def shorten_int_uuid(uuid):
-    """Encode a UUID integer in a shorter form for display.
-
-       A uuid is long. Make a shorter version that takes less room
-       in a log line.
-    """
-
-    alphabet = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz1234567890"
-    result = ""
-    while uuid:
-        uuid, t = divmod(uuid, len(alphabet))
-        result += alphabet[t]
-    return result or "0"
-
-
 def gen_trace_id():
-    """Decorator to generate a trace id (encoded uuid4) and add to contextvar
+    """Decorator to generate a trace id (nanoid or encoded uuid4) as contextvar
 
        The logging routine uses this to label every log line. All
        logs with the same trace_id should be generated from a
@@ -84,15 +135,22 @@
        used by a different invocation method. It will not set a
        trace_id if one is already assigned.
 
-       A uuid4() is used as the uuid, but to shorten the log line,
-       the uuid4 integer is encoded into a 62 character ascii
-       alphabet (A-Za-z0-9).
+       If a uuid4() is used as the id, the uuid4 integer is encoded
+       into a 62 character alphabet (A-Za-z0-9) to shorten
+       the log line.
 
        This decorator may produce duplicate (colliding) trace_id's
        when used with multiple processes on some platforms where
        uuid.uuid4().is_safe is unknown. Probability of a collision
        is unknown.
 
+       If nanoid is used to generate the id, it is 12 chars long and
+       uses a 64 char ascii alphabet, the 62 above with '_' and '-'.
+       The shorter nanoid has < 1% chance of collision in ~4 months
+       when generating 1000 id's per second.
+
+       See the help text for the module to change how the id is
+       generated.
     """
     def decorator(func):
         @functools.wraps(func)
@@ -100,7 +158,7 @@
             prev = None
             trace_id = ctx_vars['trace_id']
             if trace_id.get() is _SENTINEL_ID:
-                prev = trace_id.set(shorten_int_uuid(uuid.uuid4().int))
+                prev = trace_id.set(idgen())
             try:
                 r = func(*args, **kwargs)
             finally:
@@ -111,6 +169,26 @@
     return decorator
 
 
+def set_processName(name):
+    """Decorator to set the processName used in the LogRecord
+    """
+    def decorator(func):
+        @functools.wraps(func)
+        def wrapper(*args, **kwargs):
+            prev = None
+            processName = ctx_vars['processName']
+            if processName.get() is _SENTINEL_PROCESSNAME:
+                prev = processName.set(name)
+            try:
+                r = func(*args, **kwargs)
+            finally:
+                if prev:
+                    processName.reset(prev)
+            return r
+        return wrapper
+    return decorator
+
+
 def store_trace_reason(location=None):
     """Decorator finds and stores a reason trace was started in contextvar.
 
@@ -195,7 +273,7 @@
 
 #Is returning a dict for this info more pythonic?
 def get_context_dict():
-    """Return dict of context var tuples ["var_name": "var_value", ...}"""
+    """Return dict of context var tuples {"var_name": "var_value", ...}"""
     return {name: ctx.get() for name, ctx in ctx_vars.items()}
 
 # Dummy no=op implementation of this module:

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