1#!/usr/bin/env python3
2
3"""Logging utilities."""
4
5# print('Import of log')
6
7import os
8import sys
9import time
10import logging
11import logging.handlers
12from datetime import datetime
13from syslog import syslog
14
15from enum import Enum
16
17try:
18 import fabulous
19 from fabulous import color as col
20
21except ImportError:
22 fabulous = None
23
24try:
25 import _curses
26 import blessings
27 term = blessings.Terminal()
28
29except ImportError:
30 blessings = None
31
32except _curses.error:
33 # this happens on kde terminal under x2go...
34 blessings = None
35
36from chart.project import settings
37
38class Theme(Enum):
39 NONE = 'none'
40 FABULOUS_8BIT = 'fabulous_8bit'
41 FABULOUS = 'fabulous'
42 BLESSINGS = 'blessings'
43 CUSTOM = 'custom'
44
45theme = Theme(settings.COLOUR_THEME)
46if settings.DEBUG_LOG:
47 print('theme is {t}'.format(t=theme))
48
49# Why not try these for more terminal tricks.
50# python -m fabulous.demo
51# python -m fabulous.image <filename>
52# python -m fabulous.text --skew=4 --shadow hello kitty
53
54def rgb_to_term256(r, g, b):
55 """Convert an RGB colour (integer, 0-255) to a 256 colour terminal code.
56 From https://www.reddit.com/r/programming/comments/yeudv/blessings_15_a_python_replacement_\
57 for_curses/c5v05eo
58 """
59 if r == g == b:
60 offset = int(r // (256.0 / 24.0))
61 index = 232 + offset
62
63 else:
64 roundint = lambda n, p: (n + p // 2) // p * p
65
66 # Technically this ought to clamp to 0x5f, 0x87, 0xaf, and 0xd7
67 # rather than 0x33, 0x66, 0x99, and 0xcc, but who the hell came
68 # up with that? Seriously.
69 clamped_r = roundint(r, 0x33)
70 clamped_g = roundint(g, 0x33)
71 clamped_b = roundint(b, 0x33)
72
73 col = clamped_b // 0x33
74 row = clamped_g // 0x33
75 face = clamped_r // 0x33
76 index = 36 * face + 6 * row + col + 16
77
78 return index
79 # return self.color(index)
80
81# Drop down to less complex encodings if fabulous/blessings are not available
82# or if we are streaming to file
83if theme in (Theme.FABULOUS, Theme.FABULOUS_8BIT) and fabulous is None:
84 theme = Theme.NONE
85
86if theme is Theme.BLESSINGS and blessings is None:
87 theme = Theme.NONE
88
89if os.environ.get('INSIDE_EMACS') is not None:
90 if blessings is not None:
91 theme = Theme.FABULOUS_8BIT
92
93 else:
94 theme = Theme.NONE
95
96if not hasattr(sys.stdout, 'isatty') or \
97 not sys.stdout.isatty() or \
98 settings.SINGLE_LOG_FILE is not None or \
99 settings.ROTATING_LOG_FILE is not None:
100 theme = Theme.NONE
101
102# greyscale palette
103# #000000
104# #101010
105# #202020
106# #303030
107# #404040
108# #505050
109# #606060
110# #707070
111# #808080
112# #909090
113# #a0a0a0
114# #b0b0b0
115# #c0c0c0
116# #d0d0d0
117# #e0e0e0
118# #f0f0f0
119
120# base16 palette
121palette = {
122 'base00': '#151515',
123 'base01': '#202020',
124 'base02': '#303030',
125 'base03': '#505050',
126 'base03.5': '#909090',
127 'base04': '#b0b0b0',
128 'base05': '#d0d0d0',
129 'base06': '#e0e0e0',
130 'base07': '#f5f5f5',
131 'base08': '#ac4142',
132 'base09': '#d28445',
133 'base0A': '#f4bf75',
134 'base0B': '#90a959',
135 'base0C': '#75b5aa',
136 'base0D': '#6a9fb5',
137 'base0E': '#aa759f',
138 'base0F': '#8f5536',
139 }
140
141def bless(pal, text):
142 """Mark up string `text` to appear in foreground `col` using blessings library.
143 `pal` is selected from palette above
144 """
145 # return term.color(rgb_to_term256(*(int(s, 16) for s in (col[1:3], col[3:5], col[5:7])))) +\
146 # text +\
147 # term.normal
148
149 # `col` is a string in format #RRGGBB
150 col = palette[pal]
151 code = rgb_to_term256(*(int(s, 16) for s in (col[1:3], col[3:5], col[5:7])))
152 return term.color(code) + text + term.normal
153
154if theme is Theme.FABULOUS_8BIT:
155 if settings.DEBUG_LOG:
156 if theme == '8bit':
157 print('8-bit colour theme selected')
158
159 else:
160 print('8-bit colour theme forced as we are inside emacs ansi-term')
161
162 # an 8-bit colour theme. Forced if we are running inside an emacs ansi-term shell.
163 messagefmt = {
164 None: '{asctime} {module} {levelname} {msg}'.format(
165 asctime=col.blue('{r.asctime}'),
166 # asctime=col.highlight_blue('{r.asctime}'),
167 module=col.cyan(('{r.module}')),
168 levelname=col.green('{r.levelname}'),
169 msg=col.bold(col.yellow('{r.msg}')),
170 ),
171
172 'INFO': '{asctime} {module} {levelname} {msg}'.format(
173 asctime=col.blue('{r.asctime}'),
174 # asctime=col.highlight_blue('{r.asctime}'),
175 module=col.cyan(('{r.module}')),
176 levelname=col.bold(col.green('{r.levelname}')),
177 msg=col.bold(col.yellow('{r.msg}')),
178 ),
179
180 'WARNING': '{asctime} {module} {levelname} {msg}'.format(
181 asctime=col.blue('{r.asctime}'),
182 # asctime=col.highlight_blue('{r.asctime}'),
183 module=col.cyan(('{r.module}')),
184 levelname=col.bold(col.magenta('{r.levelname}')),
185 msg=col.bold(col.yellow('{r.msg}')),
186 ),
187
188 'ERROR': '{asctime} {module} {levelname} {msg}'.format(
189 asctime=col.blue('{r.asctime}'),
190 # asctime=col.highlight_blue('{r.asctime}'),
191 module=col.cyan(('{r.module}')),
192 levelname=col.red('{r.levelname}'),
193 msg=col.red('{r.msg}'),
194 ),
195
196 'CRITICAL': '{asctime} {module} {levelname} {msg}'.format(
197 asctime=col.blue('{r.asctime}'),
198 # asctime=col.highlight_blue('{r.asctime}'),
199 module=col.cyan(('{r.module}')),
200 levelname=col.red('{r.levelname}'),
201 msg=col.red('{r.msg}'),
202 ),
203 }
204
205elif theme is Theme.FABULOUS:
206 # if settings.DEBUG_LOG:
207 # print('Selected pastel 256-colour theme')
208
209 messagefmt = {
210 None: '{asctime} {module} {levelname} {msg}'.format(
211 asctime=col.fg256(palette['base03.5'], '{r.asctime}'),
212 module=col.fg256(palette['base0D'], '{r.module}'),
213 levelname=col.fg256(palette['base0B'], '{r.levelname}'),
214 msg=col.fg256(palette['base0E'], '{r.msg}'),
215 ),
216 'INFO': '{asctime} {module} {levelname} {msg}'.format(
217 asctime=col.fg256(palette['base03.5'], '{r.asctime}'),
218 module=col.fg256(palette['base0D'], '{r.module}'),
219 levelname=col.bold(col.fg256(palette['base0B'], '{r.levelname}')),
220 # levelname=col.fg256(palette['base06'], '{r.levelname}'),
221 msg=col.fg256(palette['base0E'], '{r.msg}'),
222 ),
223 'WARNING': '{asctime} {module} {levelname} {msg}'.format(
224 asctime=col.fg256(palette['base03.5'], '{r.asctime}'),
225 module=col.fg256(palette['base0D'], '{r.module}'),
226 levelname=col.fg256(palette['base0A'], '{r.levelname}'),
227 msg=col.fg256(palette['base0E'], '{r.msg}'),
228 ),
229 'ERROR': '{asctime} {module} {levelname} {msg}'.format(
230 asctime=col.fg256(palette['base03.5'], '{r.asctime}'),
231 module=col.fg256(palette['base0D'], '{r.module}'),
232 levelname=col.fg256(palette['base08'], '{r.levelname}'),
233 msg=col.fg256(palette['base08'], '{r.msg}'),
234 ),
235 'CRITICAL': '{asctime} {module} {levelname} {msg}'.format(
236 asctime=col.fg256(palette['base03.5'], '{r.asctime}'),
237 module=col.fg256(palette['base0D'], '{r.module}'),
238 levelname=col.bold(col.fg256(palette['base08'], '{r.levelname}')),
239 msg=col.bold(col.fg256(palette['base08'], '{r.msg}')),
240 ),
241 }
242
243elif theme is Theme.BLESSINGS:
244 messagefmt = {
245 None: '{asctime} {module} {levelname} {msg}'.format(
246 asctime=bless('base03.5', '{r.asctime}'),
247 module=bless('base0D', '{r.module}'),
248 levelname=bless('base0B', '{r.levelname}'),
249 msg=bless('base0E', '{r.msg}'),
250 ),
251 'INFO': '{asctime} {module} {levelname} {msg}'.format(
252 asctime=bless('base03.5', '{r.asctime}'),
253 module=bless('base0D', '{r.module}'),
254 levelname=term.bold(bless('base0B', '{r.levelname}')),
255 # levelname=bless('base06', '{r.levelname}'),
256 msg=bless('base0E', '{r.msg}'),
257 ),
258 'WARNING': '{asctime} {module} {levelname} {msg}'.format(
259 asctime=bless('base03.5', '{r.asctime}'),
260 module=bless('base0D', '{r.module}'),
261 levelname=bless('base0A', '{r.levelname}'),
262 msg=bless('base0E', '{r.msg}'),
263 ),
264 'ERROR': '{asctime} {module} {levelname} {msg}'.format(
265 asctime=bless('base03.5', '{r.asctime}'),
266 module=bless('base0D', '{r.module}'),
267 levelname=bless('base08', '{r.levelname}'),
268 msg=bless('base08', '{r.msg}'),
269 ),
270 'CRITICAL': '{asctime} {module} {levelname} {msg}'.format(
271 asctime=bless('base03.5', '{r.asctime}'),
272 module=bless('base0D', '{r.module}'),
273 levelname=term.bold(bless('base08', '{r.levelname}')),
274 msg=term.bold(bless('base08', '{r.msg}')),
275 ),
276 }
277
278elif theme is Theme.NONE:
279 # no terminal colours
280 if settings.DEBUG_LOG:
281 if fabulous is None:
282 print('Disabling colour output because fabulous library not found')
283
284 elif theme is Theme.NONE:
285 print('Disabling colour output because settings.COLOUR_THEME is null')
286
287 elif settings.SINGLE_LOG_FILE is not None or settings.ROTATING_LOG_FILE is not None:
288 print('Disabling colour output because we are writing to a log file')
289
290 else:
291 print('Disabling colour output because stdout is not a terminal')
292
293 # Use a colour-free log message format
294 messagefmt = {None: '{r.asctime} {r.module} {r.levelname} {r.msg}'}
295
296else:
297 raise ValueError('Theme {theme} not found'.format(theme=theme))
298
299# global logging date format
300datefmt = '%Y-%m-%d %H:%M:%S'
301
302
303class Formatter:
304 """Variation on logging.Formatter which uses different formats dependingx
305 on the log level.
306 """
307 def __init__(self, fmt):
308 """`fmt` is a dictionary mapping log levels against the format string to use
309 at that level."""
310 self.fmt = fmt
311
312 def format(self, record):
313 """
314 record contents available:
315
316 created 1374882991.29
317 exc_info None
318 exc_text None
319 filename env.py
320 funcName main
321 levelname DEBUG
322 levelno 10
323 lineno 32
324 module env
325 msecs 291.249990463
326 msg Hello I am debug message
327 name root
328 pathname /localhome/mje/Work/chart/chart/tools/env.py
329 process 25037
330 processName MainProcess
331 relativeCreated 50.5659580231
332 thread 139741536122624
333 threadName MainThread
334
335 Levels:
336 debug
337 info
338 warning
339 error
340 critical
341
342 """
343 # print('The logger name is ' + str(record.name))
344 # print('message ' + record.msg)
345 # print('The module is ' + str(record.module))
346
347 if record.module == 'ucmclient' and os.environ.get('CHART_TRUNCATE_UCM_LOG'):
348 if len(record.msg) > 60:
349 record.msg = record.msg[:60].replace('\n', '') + '...'
350
351 if sys.version_info.major == 2 and isinstance(record.msg, str):
352 record.msg = record.msg.encode('utf-8')
353
354 # we may encounter something like logging.debug(type(a))
355 if not isinstance(record.msg, str):
356 record.msg = str(record.msg)
357
358 # sometimes the actual message body we are given needs to be expanded first
359 if '%s' in record.msg:
360 try:
361 record.msg = record.msg % record.args
362 except AttributeError:
363 # weird error on OPE running apt-event
364 record.msg = '<log error>'
365
366 except TypeError as e:
367 print('Error formatting log message exc {e} msg {msg} args {args}'.format(
368 e=e, msg=record.msg, args=record.args))
369
370 # find the correct log message template for this level
371 fmt = self.fmt.get(record.levelname)
372 if fmt is None:
373 fmt = self.fmt[None]
374
375 # perform our own custom datetime formatting
376 record.asctime = datetime.fromtimestamp(record.created).strftime(datefmt)
377
378 # if record.module == '__init__':
379 # record.module == 'x'
380
381 return fmt.format(r=record)
382
383
384# done_init = False
385
386
387def init_log(messages_only=False, stderr=True): # _ = None):
388 """Configure and initialise logging.
389 If CHART_LOG_FILE is set, we log to there.
390 (If CHART_ROTATING_LOG_FILE is set, we start a daily rotating log file with given base name)
391 Otherwise we write to terminal.
392
393 If `messages_only` is set we log the logging message only (no level, timestamp or module name).
394 """
395 # global done_init
396 global messagefmt # so we can override it if needed
397
398 if init_log.done:
399 return
400
401 if len(os.environ.get('CHART_DEFAULT_LOG', '')) > 1:
402 # attempt to solve weird nosetests problem.
403 return
404
405 if settings.DEBUG_LOG:
406 print('Init of log')
407
408 # log in UTC time (does not work)
409 init_tz()
410
411 logger = logging.getLogger()
412 logger.setLevel(settings.LOG_LEVEL)
413
414 matplotlib_logger = logging.getLogger('matplotlib')
415 matplotlib_logger.setLevel(logging.ERROR)
416
417 # ??? !!! why is this needed ???
418 while len(logger.handlers) > 0:
419 logger.removeHandler(logger.handlers[0])
420 # print('Remving handler')
421 # if not done we get duplicated messages to terminal
422
423 if messages_only:
424 messagefmt = {
425 None: '{r.msg}',
426 }
427
428 # give priority to single log file
429 if settings.SINGLE_LOG_FILE is not None:
430 if settings.DEBUG_LOG:
431 print('Writing log file to {path}'.format(path=settings.SINGLE_LOG_FILE))
432
433 filehandler = logging.FileHandler(str(settings.SINGLE_LOG_FILE))
434 filehandler.setFormatter(Formatter(messagefmt))
435 logger.addHandler(filehandler)
436
437 # only use rotating log file is single is not set. this is needed for the daily digest to find
438 # them
439 elif settings.ROTATING_LOG_FILE is not None:
440 if settings.DEBUG_LOG:
441 print('Writing rotating log file to {path}'.format(path=settings.ROTATING_LOG_FILE))
442
443 # Another attempt to log in UTC time (does not work)
444 # formatter = Formatter(messagefmt)
445 # def aaa(tim):
446 # result = time.gmtime
447 # print("tim",tim,"result",result)
448 # return result
449 # formatter.converter = aaa
450 filehandler = logging.handlers.TimedRotatingFileHandler(
451 filename=str(settings.ROTATING_LOG_FILE),
452 when='midnight',
453 backupCount=settings.LOG_ROTATE_COUNT,
454 utc=True)
455 filehandler.setFormatter(Formatter(messagefmt))
456 # filehandler.setFormatter(formatter)
457 logger.addHandler(filehandler)
458
459 else:
460 if settings.DEBUG_LOG:
461 print('Logging to stdout')
462
463 # force log messages to stderr if $CHART_LOG_TO_STDERR is set
464 if stderr or settings.LOG_TO_STDERR:
465 streamhandler = logging.StreamHandler(sys.stderr)
466
467 else:
468 streamhandler = logging.StreamHandler(sys.stdout)
469
470 streamhandler.setFormatter(Formatter(messagefmt))
471 logger.addHandler(streamhandler)
472
473 # create user log
474 # if settings.ROTATING_LOG_FILE is not None:
475 # user_handler = logging.handlers.TimedRotatingFileHandler(
476 # filename=str(settings.USER_LOG_FILE),
477 # when='midnight',
478 # backupCount=settings.LOG_ROTATE_COUNT,
479 # utc=True)
480 # user_handler.setFormatter(Formatter(messagefmt))
481 # user_logger = logging.getLogger('user')
482 # user_logger.setLevel(settings.LOG_LEVEL)
483 # user_logger.addHandler(user_handler)
484 # user_logger.propagate = False
485
486 # disable spurious messages from Pillow when rendering Graph widgets
487 # disabled as the import line takes 1-2s on the TCE
488 # try:
489 # import PIL.PngImagePlugin
490 # logging.getLogger('PIL.PngImagePlugin').setLevel(100)
491
492 # except ImportError:
493 # pass
494
495 init_log.done = True
496
497
498init_log.done = False
499
500
501def log_exception(target):
502 """Exception logger including brief traceback."""
503 import traceback
504 exc_type, exc_value, exc_traceback = sys.exc_info()
505 mess = traceback.format_exception(exc_type, exc_value, exc_traceback)
506 for line in mess:
507 slines = line.splitlines()
508 for sline in slines:
509 target(sline)
510
511
512def init_tz():
513 """Use UTC time zone for logging."""
514 os.environ['TZ'] = 'UTC'
515 time.tzset()
516
517
518def write_to_syslog(message):
519 """Write a message to syslog if configured."""
520 if settings.LOG_TO_SYSLOG_PREFIX is not None:
521 syslog('{prefix}{message}'.format(prefix=settings.LOG_TO_SYSLOG_PREFIX,
522 message=message))