1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
|
The LibrarianFormatter works just like a normal logger.Formatter if there
is no Librarian available or active
>>> from lp.services.scripts.logger import LibrarianFormatter
This is a helper to quickly construct a Logger instance with a particular
formatter. Each call generates a unique Logger.
>>> _count = 0
>>> def make_logger(formatter_class):
... global _count
... _count += 1
... logger = logging.getLogger('log%d' % _count)
... output = StringIO()
... handler = logging.StreamHandler(output)
... # Note - no timestamp so we can make valid comparisons!
... formatter = formatter_class(fmt='%(levelname)s %(message)s')
... handler.setFormatter(formatter)
... logger.addHandler(handler)
... logger.setLevel(logging.DEBUG)
... logger.propagate = False
... return logger, output
Create an exception we can reuse
>>> try:
... raise RuntimeError('An Exception')
... except RuntimeError:
... exception = sys.exc_info()
Because no Librarian is running, output from the two loggers should be
identical. Note the overhead involved in attempting to contact the
Librarian is not significant.
>>> from lp.testing.layers import LibrarianLayer
>>> LibrarianLayer.hide()
>>> from lp.services.utils import utc_now
>>> normal_log, normal_out= make_logger(logging.Formatter)
>>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
>>> import time
>>> start_time = time.time()
>>> for log in (normal_log, librarian_log):
... log.error('Blah!', exc_info=exception)
>>> end_time = time.time()
>>> (end_time - start_time) < 5.0
True
>>> print normal_out.getvalue()
ERROR Blah!
Traceback (most recent call last):
...
RuntimeError: An Exception
<BLANKLINE>
>>> print librarian_out.getvalue()
ERROR Blah!
Traceback (most recent call last):
...
RuntimeError: An Exception
<BLANKLINE>
>>> normal_out.getvalue() == librarian_out.getvalue()
True
Now if we fire up the Librarian, the LibrarianFormatter should start
storing tracebacks there instead, reducing the verbosity of spam from
cronjobs
>>> LibrarianLayer.reveal()
>>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
>>> librarian_log.error('Oops', exc_info=exception)
>>> print librarian_out.getvalue()
ERROR Oops
-> http://.../....txt (An Exception)
>>> url = librarian_out.getvalue().splitlines()[-1].split()[1:2][0]
>>> print url
http://.../....txt
>>> print urlopen(url).read()
Traceback (most recent call last):
...
RuntimeError: An Exception
As the librarian commits to the test database in a subprocess, we need
to force the DatabaseLayer to fully tear down and restore the database
after this test.
>>> from lp.testing.layers import DatabaseLayer
>>> DatabaseLayer.force_dirty_database()
We keep exceptions from expiring for about 3 months.
>>> match = re.search('/(\d+)/', url)
>>> alias_id = match.group(1)
>>> from lp.services.librarian.model import LibraryFileAlias
>>> transaction.abort() # To see db changes made by the librarian
>>> alias = LibraryFileAlias.get(alias_id)
>>> alias.expires > utc_now() + timedelta(days=89)
True
Note that we also need to remain informative with dud exceptions, such as
those with a non-ASCII string representation or no string representation
at all
>>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
>>> class Dud(Exception):
... pass
>>> try:
... raise Dud()
... except Dud:
... librarian_log.exception('Dud1')
>>> try:
... raise Dud(u'\N{BIOHAZARD SIGN}'.encode('utf8'))
... except Dud:
... librarian_log.exception('Dud2')
>>> print librarian_out.getvalue()
ERROR Dud1
-> http://.../....txt (Dud)
ERROR Dud2
-> http://.../....txt (Dud)
<BLANKLINE>
The end result of this is to not have scripts display exceptions to
stderr, instead reporting URLs and greatly reducing the verbosity.
>>> script = os.path.join(this_directory, 'raiseexception.py')
>>> import subprocess
>>> p = subprocess.Popen([sys.executable, script], stdin=subprocess.PIPE,
... stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
>>> (out, err) = p.communicate()
>>> p.returncode
0
>>> print out
Script Output
ERROR Oops
-> http://.../....txt (Aargh)
ERROR Root oops
-> http://.../....txt (Aargh)
|