|
1
|
|
|
#!/usr/bin/env python |
|
2
|
|
|
# -*- coding: UTF-8 -*- |
|
3
|
|
|
|
|
4
|
|
|
# Isomer - The distributed application framework |
|
5
|
|
|
# ============================================== |
|
6
|
|
|
# Copyright (C) 2011-2020 Heiko 'riot' Weinen <[email protected]> and others. |
|
7
|
|
|
# |
|
8
|
|
|
# This program is free software: you can redistribute it and/or modify |
|
9
|
|
|
# it under the terms of the GNU Affero General Public License as published by |
|
10
|
|
|
# the Free Software Foundation, either version 3 of the License, or |
|
11
|
|
|
# (at your option) any later version. |
|
12
|
|
|
# |
|
13
|
|
|
# This program is distributed in the hope that it will be useful, |
|
14
|
|
|
# but WITHOUT ANY WARRANTY; without even the implied warranty of |
|
15
|
|
|
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the |
|
16
|
|
|
# GNU Affero General Public License for more details. |
|
17
|
|
|
# |
|
18
|
|
|
# You should have received a copy of the GNU Affero General Public License |
|
19
|
|
|
# along with this program. If not, see <http://www.gnu.org/licenses/>. |
|
20
|
|
|
|
|
21
|
|
|
""" |
|
22
|
|
|
Module: Logger |
|
23
|
|
|
============== |
|
24
|
|
|
|
|
25
|
|
|
Isomer's own logger to avoid namespace clashes etc. Comes with some fancy |
|
26
|
|
|
functions. |
|
27
|
|
|
|
|
28
|
|
|
Log Levels |
|
29
|
|
|
---------- |
|
30
|
|
|
|
|
31
|
|
|
verbose = 5 |
|
32
|
|
|
debug = 10 |
|
33
|
|
|
info = 20 |
|
34
|
|
|
warn = 30 |
|
35
|
|
|
error = 40 |
|
36
|
|
|
critical = 50 |
|
37
|
|
|
off = 100 |
|
38
|
|
|
|
|
39
|
|
|
|
|
40
|
|
|
""" |
|
41
|
|
|
|
|
42
|
|
|
# from circuits.core import Event |
|
43
|
|
|
import random |
|
44
|
|
|
import string |
|
45
|
|
|
import pprint |
|
46
|
|
|
import tempfile |
|
47
|
|
|
from traceback import format_exception |
|
48
|
|
|
|
|
49
|
|
|
# from circuits import Component, handler |
|
50
|
|
|
# from uuid import uuid4 |
|
51
|
|
|
# import json |
|
52
|
|
|
|
|
53
|
|
|
|
|
54
|
|
|
import time |
|
55
|
|
|
import datetime |
|
56
|
|
|
import sys |
|
57
|
|
|
import inspect |
|
58
|
|
|
|
|
59
|
|
|
import os |
|
60
|
|
|
|
|
61
|
|
|
root = None |
|
62
|
|
|
|
|
63
|
|
|
temp = 1 |
|
64
|
|
|
events = 2 |
|
65
|
|
|
network = 4 |
|
66
|
|
|
verbose = 5 |
|
67
|
|
|
debug = 10 |
|
68
|
|
|
info = 20 |
|
69
|
|
|
warn = 30 |
|
70
|
|
|
error = 40 |
|
71
|
|
|
critical = 50 |
|
72
|
|
|
hilight = 60 |
|
73
|
|
|
version = 99 |
|
74
|
|
|
off = 100 |
|
75
|
|
|
|
|
76
|
|
|
# https://en.wikipedia.org/wiki/ANSI_escape_code#Colors |
|
77
|
|
|
level_data = { |
|
78
|
|
|
temp: ["TEMP", "\033[1;30m"], |
|
79
|
|
|
events: ["EVENT", "\033[1:36m"], |
|
80
|
|
|
verbose: ["VERB", "\033[1;30m"], |
|
81
|
|
|
network: ["NET", "\033[1;34m"], |
|
82
|
|
|
debug: ["DEBUG", "\033[1;97m"], |
|
83
|
|
|
info: ["INFO", "\033[1;92m"], |
|
84
|
|
|
warn: ["WARN", "\033[1;93m"], |
|
85
|
|
|
error: ["ERROR", "\033[1;31;43m"], |
|
86
|
|
|
critical: ["CRIT", "\033[1;33;41m"], |
|
87
|
|
|
hilight: ["HILIGHT", "\033[1;4;34;106m"], |
|
88
|
|
|
version: ["VER", "\033[1;96;44m"], |
|
89
|
|
|
} |
|
90
|
|
|
|
|
91
|
|
|
terminator = "\033[0m" |
|
92
|
|
|
|
|
93
|
|
|
process_identifier = ''.join( |
|
94
|
|
|
[random.choice(string.ascii_letters + string.digits) for i in range(3)]) |
|
95
|
|
|
|
|
96
|
|
|
count = 0 |
|
97
|
|
|
|
|
98
|
|
|
logfile = "/var/log/isomer/service.log" |
|
99
|
|
|
log_emergency = False |
|
100
|
|
|
|
|
101
|
|
|
console = verbose |
|
102
|
|
|
live = False |
|
103
|
|
|
|
|
104
|
|
|
verbosity = {"global": console, "file": off, "system": info, "console": console} |
|
105
|
|
|
|
|
106
|
|
|
uncut = True |
|
107
|
|
|
color = False |
|
108
|
|
|
|
|
109
|
|
|
mute = [] |
|
110
|
|
|
solo = [] |
|
111
|
|
|
mark = [] |
|
112
|
|
|
|
|
113
|
|
|
LiveLog = [] |
|
114
|
|
|
|
|
115
|
|
|
start = time.time() |
|
116
|
|
|
|
|
117
|
|
|
|
|
118
|
|
|
def set_color(value: bool = True): |
|
119
|
|
|
"""Activate colorful logging""" |
|
120
|
|
|
global color |
|
121
|
|
|
color = value |
|
122
|
|
|
|
|
123
|
|
|
|
|
124
|
|
|
def set_verbosity(global_level: int, console_level: int = None, file_level: int = None): |
|
125
|
|
|
"""Adjust logging verbosity""" |
|
126
|
|
|
global verbosity |
|
127
|
|
|
|
|
128
|
|
|
if console_level is None: |
|
129
|
|
|
console_level = verbosity["console"] |
|
130
|
|
|
if file_level is None: |
|
131
|
|
|
file_level = verbosity["file"] |
|
132
|
|
|
|
|
133
|
|
|
verbosity["global"] = global_level |
|
134
|
|
|
verbosity["console"] = console_level |
|
135
|
|
|
verbosity["file"] = file_level |
|
136
|
|
|
|
|
137
|
|
|
|
|
138
|
|
|
def get_verbosity(): |
|
139
|
|
|
"""Returns logging verbosity""" |
|
140
|
|
|
global verbosity |
|
141
|
|
|
|
|
142
|
|
|
return verbosity |
|
143
|
|
|
|
|
144
|
|
|
|
|
145
|
|
|
def set_logfile(path: str, instance: str, filename: str = None): |
|
146
|
|
|
""" |
|
147
|
|
|
Specify logfile path |
|
148
|
|
|
|
|
149
|
|
|
:param path: Path to the logfile |
|
150
|
|
|
:param instance: Name of the instance |
|
151
|
|
|
:param filename: Exact name of logfile |
|
152
|
|
|
""" |
|
153
|
|
|
|
|
154
|
|
|
global logfile |
|
155
|
|
|
|
|
156
|
|
|
if path is None: |
|
157
|
|
|
path = "." |
|
158
|
|
|
|
|
159
|
|
|
if filename is not None: |
|
160
|
|
|
logfile = os.path.join(os.path.normpath(path), filename) |
|
161
|
|
|
else: |
|
162
|
|
|
logfile = os.path.join(os.path.normpath(path), "isomer." + instance + ".log") |
|
163
|
|
|
|
|
164
|
|
|
|
|
165
|
|
|
def get_logfile() -> str: |
|
166
|
|
|
"""Return the whole filename of the logfile""" |
|
167
|
|
|
return logfile |
|
168
|
|
|
|
|
169
|
|
|
|
|
170
|
|
|
def clear(): |
|
171
|
|
|
"""Clear the live log""" |
|
172
|
|
|
global LiveLog |
|
173
|
|
|
|
|
174
|
|
|
LiveLog = [] |
|
175
|
|
|
|
|
176
|
|
|
|
|
177
|
|
|
def is_muted(what) -> bool: |
|
178
|
|
|
""" |
|
179
|
|
|
Checks if a logged event is to be muted for debugging purposes. |
|
180
|
|
|
|
|
181
|
|
|
Also goes through the solo list - only items in there will be logged! |
|
182
|
|
|
|
|
183
|
|
|
:param what: |
|
184
|
|
|
""" |
|
185
|
|
|
|
|
186
|
|
|
state = False |
|
187
|
|
|
|
|
188
|
|
|
for item in solo: |
|
189
|
|
|
if item not in what: |
|
190
|
|
|
state = True |
|
191
|
|
|
else: |
|
192
|
|
|
state = False |
|
193
|
|
|
break |
|
194
|
|
|
|
|
195
|
|
|
for item in mute: |
|
196
|
|
|
if item in what: |
|
197
|
|
|
state = True |
|
198
|
|
|
break |
|
199
|
|
|
|
|
200
|
|
|
return state |
|
201
|
|
|
|
|
202
|
|
|
|
|
203
|
|
|
def is_marked(what) -> bool: |
|
204
|
|
|
"""Check if log line qualifies for highlighting""" |
|
205
|
|
|
|
|
206
|
|
|
for item in mark: |
|
207
|
|
|
if item in what: |
|
208
|
|
|
return True |
|
209
|
|
|
|
|
210
|
|
|
return False |
|
211
|
|
|
|
|
212
|
|
|
|
|
213
|
|
|
def setup_root(new_root: "isomer.components.Component"): |
|
214
|
|
|
""" |
|
215
|
|
|
Sets up the root component, so the logger knows where to send logging |
|
216
|
|
|
signals. |
|
217
|
|
|
|
|
218
|
|
|
:param isomer.components.Component new_root: |
|
219
|
|
|
""" |
|
220
|
|
|
global root |
|
221
|
|
|
|
|
222
|
|
|
root = new_root |
|
223
|
|
|
|
|
224
|
|
|
|
|
225
|
|
|
# noinspection PyUnboundLocalVariable,PyIncorrectDocstring |
|
226
|
|
|
def isolog(*what, **kwargs): |
|
227
|
|
|
"""Logs all non keyword arguments. |
|
228
|
|
|
|
|
229
|
|
|
:param tuple/str what: Loggable objects (i.e. they have a string |
|
230
|
|
|
representation) |
|
231
|
|
|
:param int lvl: Debug message level |
|
232
|
|
|
:param str emitter: Optional log source, where this can't be determined |
|
233
|
|
|
automatically |
|
234
|
|
|
:param str sourceloc: Give specific source code location hints, used |
|
235
|
|
|
internally |
|
236
|
|
|
:param int frameref: Specify a non default frame for tracebacks |
|
237
|
|
|
:param bool tb: Include a traceback |
|
238
|
|
|
:param bool nc: Do not use color |
|
239
|
|
|
:param bool exc: Switch to better handle exceptions, use if logging in an |
|
240
|
|
|
except clause |
|
241
|
|
|
|
|
242
|
|
|
""" |
|
243
|
|
|
|
|
244
|
|
|
global count |
|
245
|
|
|
global verbosity |
|
246
|
|
|
|
|
247
|
|
|
lvl = kwargs.get("lvl", info) |
|
248
|
|
|
|
|
249
|
|
|
if lvl < verbosity["global"]: |
|
250
|
|
|
return |
|
251
|
|
|
|
|
252
|
|
|
def assemble_things(things) -> str: |
|
253
|
|
|
result = "" |
|
254
|
|
|
|
|
255
|
|
|
for thing in things: |
|
256
|
|
|
result += " " |
|
257
|
|
|
if kwargs.get("pretty", False) and not isinstance(thing, str): |
|
258
|
|
|
result += "\n" + pprint.pformat(thing) |
|
259
|
|
|
else: |
|
260
|
|
|
result += str(thing) |
|
261
|
|
|
|
|
262
|
|
|
return result |
|
263
|
|
|
|
|
264
|
|
|
def write_to_log(message: str): |
|
265
|
|
|
global logfile |
|
266
|
|
|
|
|
267
|
|
|
while True: |
|
268
|
|
|
try: |
|
269
|
|
|
f = open(logfile, "a") |
|
270
|
|
|
f.write(message + "\n") |
|
271
|
|
|
f.flush() |
|
272
|
|
|
f.close() |
|
273
|
|
|
|
|
274
|
|
|
break |
|
275
|
|
|
except IOError: |
|
276
|
|
|
global log_emergency |
|
277
|
|
|
print("Cannot open logfile '%s' for writing" % logfile) |
|
278
|
|
|
|
|
279
|
|
|
if log_emergency is True: |
|
280
|
|
|
print( |
|
281
|
|
|
"Safe temporary logging is not working either, " |
|
282
|
|
|
"giving up on file logging" |
|
283
|
|
|
) |
|
284
|
|
|
break |
|
285
|
|
|
|
|
286
|
|
|
logfile = os.path.join( |
|
287
|
|
|
tempfile.mkdtemp(prefix="isomer_"), |
|
288
|
|
|
"emergency_log" |
|
289
|
|
|
) |
|
290
|
|
|
print("Logging to temporary logfile '%s'" % logfile) |
|
291
|
|
|
log_emergency = True |
|
292
|
|
|
|
|
293
|
|
|
continue |
|
294
|
|
|
|
|
295
|
|
|
def write_to_console(message: str): |
|
296
|
|
|
try: |
|
297
|
|
|
print(message) |
|
298
|
|
|
except UnicodeEncodeError as e: |
|
299
|
|
|
print(message.encode("utf-8")) |
|
300
|
|
|
isolog("Bad encoding encountered on previous message:", e, lvl=error) |
|
301
|
|
|
except BlockingIOError: |
|
302
|
|
|
isolog("Too long log line encountered:", message[:20], lvl=warn) |
|
303
|
|
|
|
|
304
|
|
|
# Count all messages (missing numbers give a hint at too high log level) |
|
305
|
|
|
count += 1 |
|
306
|
|
|
|
|
307
|
|
|
emitter = kwargs.get("emitter", "UNKNOWN") |
|
308
|
|
|
traceback = kwargs.get("tb", False) |
|
309
|
|
|
frame_ref = kwargs.get("frame_ref", 0) |
|
310
|
|
|
no_color = kwargs.get("nc", False) |
|
311
|
|
|
exception = kwargs.get("exc", False) |
|
312
|
|
|
|
|
313
|
|
|
timestamp = time.time() |
|
314
|
|
|
runtime = timestamp - start |
|
315
|
|
|
callee = None |
|
316
|
|
|
|
|
317
|
|
|
if exception: |
|
318
|
|
|
exc_type, exc_obj, exc_tb = sys.exc_info() # NOQA |
|
319
|
|
|
|
|
320
|
|
|
if verbosity["global"] <= debug or traceback: |
|
321
|
|
|
# Automatically log the current function details. |
|
322
|
|
|
|
|
323
|
|
|
if "sourceloc" not in kwargs: |
|
324
|
|
|
frame = kwargs.get("frame", frame_ref) |
|
325
|
|
|
|
|
326
|
|
|
# Get the previous frame in the stack, otherwise it would |
|
327
|
|
|
# be this function |
|
328
|
|
|
current_frame = inspect.currentframe() |
|
329
|
|
|
while frame > 0: |
|
330
|
|
|
frame -= 1 |
|
331
|
|
|
current_frame = current_frame.f_back |
|
332
|
|
|
|
|
333
|
|
|
func = current_frame.f_code |
|
334
|
|
|
# Dump the message + the name of this function to the log. |
|
335
|
|
|
|
|
336
|
|
|
if exception: |
|
337
|
|
|
# noinspection PyUnboundLocalVariable |
|
338
|
|
|
line_no = exc_tb.tb_lineno |
|
|
|
|
|
|
339
|
|
|
if lvl <= error: |
|
340
|
|
|
lvl = error |
|
341
|
|
|
else: |
|
342
|
|
|
line_no = func.co_firstlineno |
|
343
|
|
|
|
|
344
|
|
|
callee = "[%.10s@%s:%i]" % (func.co_name, func.co_filename, line_no) |
|
345
|
|
|
else: |
|
346
|
|
|
callee = kwargs["sourceloc"] |
|
347
|
|
|
|
|
348
|
|
|
now = datetime.datetime.now().isoformat() |
|
349
|
|
|
msg = "[%s]:[%s]:%s:%.5f:%3i: [%5s]" % ( |
|
350
|
|
|
now, |
|
351
|
|
|
process_identifier, |
|
352
|
|
|
level_data[lvl][0], |
|
353
|
|
|
runtime, |
|
354
|
|
|
count, |
|
355
|
|
|
emitter, |
|
356
|
|
|
) |
|
357
|
|
|
|
|
358
|
|
|
if callee: |
|
359
|
|
|
if not uncut and lvl > 10: |
|
360
|
|
|
msg += "%-60s" % callee |
|
361
|
|
|
else: |
|
362
|
|
|
msg += "%s" % callee |
|
363
|
|
|
|
|
364
|
|
|
content = assemble_things(what) |
|
365
|
|
|
msg += content |
|
366
|
|
|
|
|
367
|
|
|
if exception: |
|
368
|
|
|
msg += "\n" + "".join(format_exception(exc_type, exc_obj, exc_tb)) |
|
|
|
|
|
|
369
|
|
|
|
|
370
|
|
|
if is_muted(msg): |
|
371
|
|
|
return |
|
372
|
|
|
|
|
373
|
|
|
if not uncut and lvl > 10 and len(msg) > 1000: |
|
374
|
|
|
msg = msg[:1000] |
|
375
|
|
|
|
|
376
|
|
|
if lvl >= verbosity["file"]: |
|
377
|
|
|
write_to_log(msg) |
|
378
|
|
|
|
|
379
|
|
|
if is_marked(msg): |
|
380
|
|
|
lvl = hilight |
|
381
|
|
|
|
|
382
|
|
|
if lvl >= verbosity["console"]: |
|
383
|
|
|
output = str(msg) |
|
384
|
|
|
if color and not no_color: |
|
385
|
|
|
output = level_data[lvl][1] + output + terminator |
|
386
|
|
|
write_to_console(output) |
|
387
|
|
|
|
|
388
|
|
|
if live: |
|
389
|
|
|
item = [now, lvl, runtime, count, emitter, str(content)] |
|
390
|
|
|
LiveLog.append(item) |
|
391
|
|
|
|