Skip to content

Commit 4913788

Browse files
committed
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.
1 parent 5c79282 commit 4913788

File tree

8 files changed

+140
-32
lines changed

8 files changed

+140
-32
lines changed

CHANGES.txt

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -54,9 +54,10 @@ Features:
5454
logging format. (John Rouillard)
5555
- the default logging format template includes an identifier unique
5656
for a request. This identifier (trace_id) can be use to identify
57-
logs for a specific transaction. Logging also supports a
58-
trace_reason log token with the url for a web request. The logging
59-
format can be changed in config.ini. (John Rouillard)
57+
logs for a specific transaction. Will use nanoid if installed, uses
58+
uuid.uuid4 otherwise. Logging also supports a trace_reason log token
59+
with the url for a web request. The logging format can be changed in
60+
config.ini. (John Rouillard)
6061

6162
2025-07-13 2.5.0
6263

doc/admin_guide.txt

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -239,8 +239,8 @@ More on trace_id
239239
~~~~~~~~~~~~~~~~
240240

241241
The trace_id provides a unique token (a UUID4 encoded to make it
242-
shorter) for each transaction in the database. It is unique to
243-
each thread or transaction. A transaction:
242+
shorter or a nanoid) for each transaction in the database. It is
243+
unique to each thread or transaction. A transaction:
244244

245245
for the web interface is
246246
each web, rest or xmlrpc request
@@ -282,7 +282,11 @@ point for the processing operation::
282282
for thing in things:
283283
process_one(thing)
284284

285+
You can change the format of the trace_id if required using the
286+
tracker's interfaces.py file. See the :ref:`module docs for the
287+
logcontext module <logcontext_pydoc>` for details.
285288

289+
286290
Advanced Logging Setup
287291
----------------------
288292

doc/installation.txt

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -253,7 +253,11 @@ gpg
253253
version 2.0 of gpg from test.pypi.org. See the `gpg install
254254
directions in the upgrading document`_.
255255

256-
256+
nanoid
257+
If nanoid_ is installed, it is used to generate short unique
258+
ids to link all logging to a single request. If not installed,
259+
uuid4's from the standard library are used.
260+
257261
jinja2
258262
To use the jinja2 template (may still be experimental, check out
259263
its TEMPLATE-INFO.txt file) you need
@@ -2432,6 +2436,7 @@ the test.
24322436
.. _mod_python: https://github.com/grisha/mod_python
24332437
.. _mod_wsgi: https://pypi.org/project/mod-wsgi/
24342438
.. _MySQLdb: https://pypi.org/project/mysqlclient/
2439+
.. _nanoid: https://pypi.org/project/nanoid/
24352440
.. _Olson tz database: https://www.iana.org/time-zones
24362441
.. _polib: https://polib.readthedocs.io
24372442
.. _Psycopg2: https://www.psycopg.org/

doc/pydoc.txt

Lines changed: 15 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,14 @@
1-
================
2-
Pydocs from code
3-
================
1+
================================
2+
Embedded documentation from code
3+
================================
44

55
.. contents::
66
:local:
77

8+
The following are embedded documentation selected from the Roundup
9+
code base. You can see the same information using the ``help``
10+
function after importing the modules.
11+
812
Client class
913
============
1014

@@ -40,3 +44,11 @@ Templating Utils class
4044

4145
.. autoclass:: roundup.cgi.templating::TemplatingUtils
4246
:members:
47+
48+
Logcontext Module
49+
=================
50+
.. _logcontext_pydoc:
51+
52+
.. automodule:: roundup.logcontext
53+
:members:
54+
:exclude-members: SimpleSentinel

roundup/admin.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -49,7 +49,7 @@
4949
)
5050
from roundup.exceptions import UsageError
5151
from roundup.i18n import _, get_translation
52-
from roundup.logcontext import gen_trace_id, store_trace_reason
52+
from roundup.logcontext import gen_trace_id, set_processName, store_trace_reason
5353

5454
try:
5555
from UserDict import UserDict
@@ -2355,6 +2355,7 @@ def usageError_feedback(self, message, function):
23552355
print(function.__doc__)
23562356
return 1
23572357

2358+
@set_processName("roundup-admin")
23582359
@gen_trace_id()
23592360
@store_trace_reason('admin')
23602361
def run_command(self, args):

roundup/cgi/wsgi_handler.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@
1313
from roundup.anypy.strings import s2b
1414
from roundup.cgi import TranslationService
1515
from roundup.cgi.client import BinaryFieldStorage
16-
from roundup.logcontext import gen_trace_id, store_trace_reason
16+
from roundup.logcontext import gen_trace_id, set_processName, store_trace_reason
1717

1818
BaseHTTPRequestHandler = http_.server.BaseHTTPRequestHandler
1919
DEFAULT_ERROR_MESSAGE = http_.server.DEFAULT_ERROR_MESSAGE
@@ -107,6 +107,7 @@ def use_cached_tracker(self):
107107
"cache_tracker" not in self.feature_flags or
108108
self.feature_flags["cache_tracker"] is not False)
109109

110+
@set_processName("wsgi_handler")
110111
@gen_trace_id()
111112
@store_trace_reason("wsgi")
112113
def __call__(self, environ, start_response):

roundup/configuration.py

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2440,6 +2440,12 @@ def context_filter(self, record):
24402440
for name, value in get_context_info():
24412441
if not hasattr(record, name):
24422442
setattr(record, name, value)
2443+
continue
2444+
if (name == "processName" and
2445+
isinstance(value, str) and
2446+
getattr(record, name) == "MainProcess"):
2447+
setattr(record, name, value)
2448+
24432449
record.pct_char = "%"
24442450
record.ROUNDUP_CONTEXT_FILTER_CALLED = True
24452451

roundup/logcontext.py

Lines changed: 99 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,70 @@
1+
"""Generate and store thread local logging context including unique
2+
trace id for request, request source etc. to be logged.
3+
4+
Trace id generator can use nanoid or uuid.uuid4 stdlib function.
5+
Nanoid is preferred if nanoid is installed using pip as nanoid is
6+
faster and generates a shorter id. If nanoid is installed in the
7+
tracker's lib subdirectory, it must be enabled using the tracker's
8+
interfaces.py by adding::
9+
10+
# if nanoid is installed in tracker's lib directory or
11+
# if you want to change the length of the nanoid from 12
12+
# to 14 chars use:
13+
from functools import partial
14+
from nanoid import generate
15+
import roundup.logcontext
16+
# change 14 to 12 to get the default nanoid size.
17+
roundup.logcontext.idgen=partial(generate, size=14)
18+
19+
# to force use of shortened uuid when nanoid is
20+
# loaded by default
21+
import roundup.logcontext
22+
roundup.logcontext.idgen=roundup.logcontext.short_uuid
23+
24+
"""
125
import contextvars
226
import functools
327
import logging
428
import os
529
import uuid
630

31+
32+
def short_uuid():
33+
"""Encode a UUID integer in a shorter form for display.
34+
35+
A uuid is long. Make a shorter version that takes less room
36+
in a log line and is easier to store.
37+
"""
38+
alphabet = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz1234567890"
39+
result = ""
40+
alphabet_len = len(alphabet)
41+
uuid_int = uuid.uuid4().int
42+
while uuid_int:
43+
uuid_int, t = divmod(uuid_int, alphabet_len)
44+
result += alphabet[t]
45+
return result or "0"
46+
47+
48+
try:
49+
from nanoid import generate
50+
# With size=12 and the normal alphabet, it take ~4 months
51+
# with 1000 nanoid's/sec to generate a collision with 1%
52+
# probability. That's 100 users sec continously. These id's
53+
# are used to link logging messages/traces that are all done
54+
# in a few seconds. Collisions ae unlikely to happen in the
55+
# same time period leading to confusion.
56+
#
57+
# nanoid is faster than shortened uuids.
58+
# 1,000,000 generate(size=12) timeit.timeit at 25.4 seconds
59+
# 1,000,000 generate(size=21) timeit.timeit at 33.7 seconds
60+
61+
#: Variable used for setting the id generator.
62+
idgen = functools.partial(generate, size=12)
63+
except ImportError:
64+
# 1,000,000 of short_uuid() timeit.timeit at 54.1 seconds
65+
idgen = short_uuid #: :meta hide-value:
66+
67+
768
logger = logging.getLogger("roundup.logcontext")
869

970

@@ -46,6 +107,11 @@ def __repr__(self):
46107

47108
# set up sentinel values that will print a suitable error value
48109
# and the context vars they are associated with.
110+
_SENTINEL_PROCESSNAME = SimpleSentinel("processName", None)
111+
ctx_vars['processName'] = contextvars.ContextVar("processName",
112+
default=_SENTINEL_PROCESSNAME)
113+
114+
49115
_SENTINEL_ID = SimpleSentinel("trace_id", "not set")
50116
ctx_vars['trace_id'] = contextvars.ContextVar("trace_id", default=_SENTINEL_ID)
51117

@@ -55,23 +121,8 @@ def __repr__(self):
55121
default=_SENTINEL_REASON)
56122

57123

58-
def shorten_int_uuid(uuid):
59-
"""Encode a UUID integer in a shorter form for display.
60-
61-
A uuid is long. Make a shorter version that takes less room
62-
in a log line.
63-
"""
64-
65-
alphabet = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz1234567890"
66-
result = ""
67-
while uuid:
68-
uuid, t = divmod(uuid, len(alphabet))
69-
result += alphabet[t]
70-
return result or "0"
71-
72-
73124
def gen_trace_id():
74-
"""Decorator to generate a trace id (encoded uuid4) and add to contextvar
125+
"""Decorator to generate a trace id (nanoid or encoded uuid4) as contextvar
75126
76127
The logging routine uses this to label every log line. All
77128
logs with the same trace_id should be generated from a
@@ -84,23 +135,30 @@ def gen_trace_id():
84135
used by a different invocation method. It will not set a
85136
trace_id if one is already assigned.
86137
87-
A uuid4() is used as the uuid, but to shorten the log line,
88-
the uuid4 integer is encoded into a 62 character ascii
89-
alphabet (A-Za-z0-9).
138+
If a uuid4() is used as the id, the uuid4 integer is encoded
139+
into a 62 character alphabet (A-Za-z0-9) to shorten
140+
the log line.
90141
91142
This decorator may produce duplicate (colliding) trace_id's
92143
when used with multiple processes on some platforms where
93144
uuid.uuid4().is_safe is unknown. Probability of a collision
94145
is unknown.
95146
147+
If nanoid is used to generate the id, it is 12 chars long and
148+
uses a 64 char ascii alphabet, the 62 above with '_' and '-'.
149+
The shorter nanoid has < 1% chance of collision in ~4 months
150+
when generating 1000 id's per second.
151+
152+
See the help text for the module to change how the id is
153+
generated.
96154
"""
97155
def decorator(func):
98156
@functools.wraps(func)
99157
def wrapper(*args, **kwargs):
100158
prev = None
101159
trace_id = ctx_vars['trace_id']
102160
if trace_id.get() is _SENTINEL_ID:
103-
prev = trace_id.set(shorten_int_uuid(uuid.uuid4().int))
161+
prev = trace_id.set(idgen())
104162
try:
105163
r = func(*args, **kwargs)
106164
finally:
@@ -111,6 +169,26 @@ def wrapper(*args, **kwargs):
111169
return decorator
112170

113171

172+
def set_processName(name):
173+
"""Decorator to set the processName used in the LogRecord
174+
"""
175+
def decorator(func):
176+
@functools.wraps(func)
177+
def wrapper(*args, **kwargs):
178+
prev = None
179+
processName = ctx_vars['processName']
180+
if processName.get() is _SENTINEL_PROCESSNAME:
181+
prev = processName.set(name)
182+
try:
183+
r = func(*args, **kwargs)
184+
finally:
185+
if prev:
186+
processName.reset(prev)
187+
return r
188+
return wrapper
189+
return decorator
190+
191+
114192
def store_trace_reason(location=None):
115193
"""Decorator finds and stores a reason trace was started in contextvar.
116194
@@ -195,7 +273,7 @@ def get_context_info():
195273

196274
#Is returning a dict for this info more pythonic?
197275
def get_context_dict():
198-
"""Return dict of context var tuples ["var_name": "var_value", ...}"""
276+
"""Return dict of context var tuples {"var_name": "var_value", ...}"""
199277
return {name: ctx.get() for name, ctx in ctx_vars.items()}
200278

201279
# Dummy no=op implementation of this module:

0 commit comments

Comments
 (0)