Mercurial > p > roundup > code

comparison roundup/logcontext.py @ 8487:b09ef85f0da6

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
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 df9fc9080e5a
children f80c566f5726
comparison
equal deleted inserted replaced
8478:ed4ef394d5d6 8487:b09ef85f0da6
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 """
1 import contextvars 25 import contextvars
2 import functools 26 import functools
3 import logging 27 import logging
4 import os 28 import os
5 import uuid 29 import uuid
30
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
6 67
7 logger = logging.getLogger("roundup.logcontext") 68 logger = logging.getLogger("roundup.logcontext")
8 69
9 70
10 class SimpleSentinel: 71 class SimpleSentinel:
44 # even if they have not been set. 105 # even if they have not been set.
45 ctx_vars = {} 106 ctx_vars = {}
46 107
47 # set up sentinel values that will print a suitable error value 108 # set up sentinel values that will print a suitable error value
48 # and the context vars they are associated with. 109 # 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
49 _SENTINEL_ID = SimpleSentinel("trace_id", "not set") 115 _SENTINEL_ID = SimpleSentinel("trace_id", "not set")
50 ctx_vars['trace_id'] = contextvars.ContextVar("trace_id", default=_SENTINEL_ID) 116 ctx_vars['trace_id'] = contextvars.ContextVar("trace_id", default=_SENTINEL_ID)
51 117
52 118
53 _SENTINEL_REASON = SimpleSentinel("trace_reason", "missing") 119 _SENTINEL_REASON = SimpleSentinel("trace_reason", "missing")
54 ctx_vars['trace_reason'] = contextvars.ContextVar("trace_reason", 120 ctx_vars['trace_reason'] = contextvars.ContextVar("trace_reason",
55 default=_SENTINEL_REASON) 121 default=_SENTINEL_REASON)
56 122
57 123
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
73 def gen_trace_id(): 124 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
75 126
76 The logging routine uses this to label every log line. All 127 The logging routine uses this to label every log line. All
77 logs with the same trace_id should be generated from a 128 logs with the same trace_id should be generated from a
78 single request. 129 single request.
79 130
82 points. As a result, this decorator can be called multiple 133 points. As a result, this decorator can be called multiple
83 times as some entry points can traverse another entry point 134 times as some entry points can traverse another entry point
84 used by a different invocation method. It will not set a 135 used by a different invocation method. It will not set a
85 trace_id if one is already assigned. 136 trace_id if one is already assigned.
86 137
87 A uuid4() is used as the uuid, but to shorten the log line, 138 If a uuid4() is used as the id, the uuid4 integer is encoded
88 the uuid4 integer is encoded into a 62 character ascii 139 into a 62 character alphabet (A-Za-z0-9) to shorten
89 alphabet (A-Za-z0-9). 140 the log line.
90 141
91 This decorator may produce duplicate (colliding) trace_id's 142 This decorator may produce duplicate (colliding) trace_id's
92 when used with multiple processes on some platforms where 143 when used with multiple processes on some platforms where
93 uuid.uuid4().is_safe is unknown. Probability of a collision 144 uuid.uuid4().is_safe is unknown. Probability of a collision
94 is unknown. 145 is unknown.
95 146
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.
96 """ 154 """
97 def decorator(func): 155 def decorator(func):
98 @functools.wraps(func) 156 @functools.wraps(func)
99 def wrapper(*args, **kwargs): 157 def wrapper(*args, **kwargs):
100 prev = None 158 prev = None
101 trace_id = ctx_vars['trace_id'] 159 trace_id = ctx_vars['trace_id']
102 if trace_id.get() is _SENTINEL_ID: 160 if trace_id.get() is _SENTINEL_ID:
103 prev = trace_id.set(shorten_int_uuid(uuid.uuid4().int)) 161 prev = trace_id.set(idgen())
104 try: 162 try:
105 r = func(*args, **kwargs) 163 r = func(*args, **kwargs)
106 finally: 164 finally:
107 if prev: 165 if prev:
108 trace_id.reset(prev) 166 trace_id.reset(prev)
167 return r
168 return wrapper
169 return decorator
170
171
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)
109 return r 187 return r
110 return wrapper 188 return wrapper
111 return decorator 189 return decorator
112 190
113 191
193 return [(name, ctx.get()) for name, ctx in ctx_vars.items()] 271 return [(name, ctx.get()) for name, ctx in ctx_vars.items()]
194 272
195 273
196 #Is returning a dict for this info more pythonic? 274 #Is returning a dict for this info more pythonic?
197 def get_context_dict(): 275 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", ...}"""
199 return {name: ctx.get() for name, ctx in ctx_vars.items()} 277 return {name: ctx.get() for name, ctx in ctx_vars.items()}
200 278
201 # Dummy no=op implementation of this module: 279 # Dummy no=op implementation of this module:
202 # 280 #
203 #def noop_decorator(*args, **kwargs): 281 #def noop_decorator(*args, **kwargs):
Roundup Issue Tracker: http://roundup-tracker.org/