changeset 8488:7142740e6547

merge heads: CHANGES.txt also whitespace fixups.
author John Rouillard <rouilj@ieee.org>
date Mon, 08 Dec 2025 23:05:26 -0500
parents e2d0f36c525d (current diff) b09ef85f0da6 (diff)
children 4e0944649af7
files CHANGES.txt doc/admin_guide.txt doc/installation.txt roundup/configuration.py
diffstat 8 files changed, 138 insertions(+), 31 deletions(-) [+]
line wrap: on
line diff
--- a/CHANGES.txt	Sun Dec 07 17:33:25 2025 -0500
+++ b/CHANGES.txt	Mon Dec 08 23:05:26 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)
 - issue2551152 - added basic PGP setup/use info to admin_guide. (John
   Rouillard)
 
--- a/doc/admin_guide.txt	Sun Dec 07 17:33:25 2025 -0500
+++ b/doc/admin_guide.txt	Mon Dec 08 23:05:26 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,6 +282,9 @@
        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	Sun Dec 07 17:33:25 2025 -0500
+++ b/doc/installation.txt	Mon Dec 08 23:05:26 2025 -0500
@@ -253,6 +253,10 @@
   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
@@ -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	Sun Dec 07 17:33:25 2025 -0500
+++ b/doc/pydoc.txt	Mon Dec 08 23:05:26 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	Sun Dec 07 17:33:25 2025 -0500
+++ b/roundup/admin.py	Mon Dec 08 23:05:26 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	Sun Dec 07 17:33:25 2025 -0500
+++ b/roundup/cgi/wsgi_handler.py	Mon Dec 08 23:05:26 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	Sun Dec 07 17:33:25 2025 -0500
+++ b/roundup/configuration.py	Mon Dec 08 23:05:26 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	Sun Dec 07 17:33:25 2025 -0500
+++ b/roundup/logcontext.py	Mon Dec 08 23:05:26 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/