Skip to content

Commit 398332d

Browse files
committed
merge heads: CHANGES.txt also whitespace fixups.
2 parents df79d29 + 4913788 commit 398332d

File tree

8 files changed

+138
-31
lines changed

8 files changed

+138
-31
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
- issue2551152 - added basic PGP setup/use info to admin_guide. (John
6162
Rouillard)
6263

doc/admin_guide.txt

Lines changed: 5 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,6 +282,9 @@ 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

286289
Advanced Logging Setup
287290
----------------------

doc/installation.txt

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

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.
256260

257261
jinja2
258262
To use the jinja2 template (may still be experimental, check out
@@ -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)