blob: 4133c30b2f74e7480cbb4a57f4b10704ff1fc4cf [file] [log] [blame]
Matthew Treinish0db53772013-07-26 10:39:35 -04001# vim: tabstop=4 shiftwidth=4 softtabstop=4
2
3# Copyright 2011 OpenStack Foundation.
4# Copyright 2010 United States Government as represented by the
5# Administrator of the National Aeronautics and Space Administration.
6# All Rights Reserved.
7#
8# Licensed under the Apache License, Version 2.0 (the "License"); you may
9# not use this file except in compliance with the License. You may obtain
10# a copy of the License at
11#
12# http://www.apache.org/licenses/LICENSE-2.0
13#
14# Unless required by applicable law or agreed to in writing, software
15# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
16# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
17# License for the specific language governing permissions and limitations
18# under the License.
19
20"""Openstack logging handler.
21
22This module adds to logging functionality by adding the option to specify
23a context object when calling the various log methods. If the context object
24is not specified, default formatting is used. Additionally, an instance uuid
25may be passed as part of the log message, which is intended to make it easier
26for admins to find messages related to a specific instance.
27
28It also allows setting of formatting information through conf.
29
30"""
31
32import inspect
33import itertools
34import logging
35import logging.config
36import logging.handlers
37import os
38import sys
39import traceback
40
41from oslo.config import cfg
42from six import moves
43
44from tempest.openstack.common.gettextutils import _ # noqa
45from tempest.openstack.common import importutils
46from tempest.openstack.common import jsonutils
47from tempest.openstack.common import local
48
49
50_DEFAULT_LOG_DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
51
52common_cli_opts = [
53 cfg.BoolOpt('debug',
54 short='d',
55 default=False,
56 help='Print debugging output (set logging level to '
57 'DEBUG instead of default WARNING level).'),
58 cfg.BoolOpt('verbose',
59 short='v',
60 default=False,
61 help='Print more verbose output (set logging level to '
62 'INFO instead of default WARNING level).'),
63]
64
65logging_cli_opts = [
66 cfg.StrOpt('log-config',
67 metavar='PATH',
68 help='If this option is specified, the logging configuration '
69 'file specified is used and overrides any other logging '
70 'options specified. Please see the Python logging module '
71 'documentation for details on logging configuration '
72 'files.'),
73 cfg.StrOpt('log-format',
74 default=None,
75 metavar='FORMAT',
76 help='DEPRECATED. '
77 'A logging.Formatter log message format string which may '
78 'use any of the available logging.LogRecord attributes. '
79 'This option is deprecated. Please use '
80 'logging_context_format_string and '
81 'logging_default_format_string instead.'),
82 cfg.StrOpt('log-date-format',
83 default=_DEFAULT_LOG_DATE_FORMAT,
84 metavar='DATE_FORMAT',
85 help='Format string for %%(asctime)s in log records. '
86 'Default: %(default)s'),
87 cfg.StrOpt('log-file',
88 metavar='PATH',
89 deprecated_name='logfile',
90 help='(Optional) Name of log file to output to. '
91 'If no default is set, logging will go to stdout.'),
92 cfg.StrOpt('log-dir',
93 deprecated_name='logdir',
94 help='(Optional) The base directory used for relative '
95 '--log-file paths'),
96 cfg.BoolOpt('use-syslog',
97 default=False,
98 help='Use syslog for logging.'),
99 cfg.StrOpt('syslog-log-facility',
100 default='LOG_USER',
101 help='syslog facility to receive log lines')
102]
103
104generic_log_opts = [
105 cfg.BoolOpt('use_stderr',
106 default=True,
107 help='Log output to standard error')
108]
109
110log_opts = [
111 cfg.StrOpt('logging_context_format_string',
112 default='%(asctime)s.%(msecs)03d %(process)d %(levelname)s '
113 '%(name)s [%(request_id)s %(user)s %(tenant)s] '
114 '%(instance)s%(message)s',
115 help='format string to use for log messages with context'),
116 cfg.StrOpt('logging_default_format_string',
117 default='%(asctime)s.%(msecs)03d %(process)d %(levelname)s '
118 '%(name)s [-] %(instance)s%(message)s',
119 help='format string to use for log messages without context'),
120 cfg.StrOpt('logging_debug_format_suffix',
121 default='%(funcName)s %(pathname)s:%(lineno)d',
122 help='data to append to log format when level is DEBUG'),
123 cfg.StrOpt('logging_exception_prefix',
124 default='%(asctime)s.%(msecs)03d %(process)d TRACE %(name)s '
125 '%(instance)s',
126 help='prefix each line of exception output with this format'),
127 cfg.ListOpt('default_log_levels',
128 default=[
129 'amqplib=WARN',
130 'sqlalchemy=WARN',
131 'boto=WARN',
132 'suds=INFO',
133 'keystone=INFO',
134 'eventlet.wsgi.server=WARN'
135 ],
136 help='list of logger=LEVEL pairs'),
137 cfg.BoolOpt('publish_errors',
138 default=False,
139 help='publish error events'),
140 cfg.BoolOpt('fatal_deprecations',
141 default=False,
142 help='make deprecations fatal'),
143
144 # NOTE(mikal): there are two options here because sometimes we are handed
145 # a full instance (and could include more information), and other times we
146 # are just handed a UUID for the instance.
147 cfg.StrOpt('instance_format',
148 default='[instance: %(uuid)s] ',
149 help='If an instance is passed with the log message, format '
150 'it like this'),
151 cfg.StrOpt('instance_uuid_format',
152 default='[instance: %(uuid)s] ',
153 help='If an instance UUID is passed with the log message, '
154 'format it like this'),
155]
156
157CONF = cfg.CONF
158CONF.register_cli_opts(common_cli_opts)
159CONF.register_cli_opts(logging_cli_opts)
160CONF.register_opts(generic_log_opts)
161CONF.register_opts(log_opts)
162
163# our new audit level
164# NOTE(jkoelker) Since we synthesized an audit level, make the logging
165# module aware of it so it acts like other levels.
166logging.AUDIT = logging.INFO + 1
167logging.addLevelName(logging.AUDIT, 'AUDIT')
168
169
170try:
171 NullHandler = logging.NullHandler
172except AttributeError: # NOTE(jkoelker) NullHandler added in Python 2.7
173 class NullHandler(logging.Handler):
174 def handle(self, record):
175 pass
176
177 def emit(self, record):
178 pass
179
180 def createLock(self):
181 self.lock = None
182
183
184def _dictify_context(context):
185 if context is None:
186 return None
187 if not isinstance(context, dict) and getattr(context, 'to_dict', None):
188 context = context.to_dict()
189 return context
190
191
192def _get_binary_name():
193 return os.path.basename(inspect.stack()[-1][1])
194
195
196def _get_log_file_path(binary=None):
197 logfile = CONF.log_file
198 logdir = CONF.log_dir
199
200 if logfile and not logdir:
201 return logfile
202
203 if logfile and logdir:
204 return os.path.join(logdir, logfile)
205
206 if logdir:
207 binary = binary or _get_binary_name()
208 return '%s.log' % (os.path.join(logdir, binary),)
209
210
211class BaseLoggerAdapter(logging.LoggerAdapter):
212
213 def audit(self, msg, *args, **kwargs):
214 self.log(logging.AUDIT, msg, *args, **kwargs)
215
216
217class LazyAdapter(BaseLoggerAdapter):
218 def __init__(self, name='unknown', version='unknown'):
219 self._logger = None
220 self.extra = {}
221 self.name = name
222 self.version = version
223
224 @property
225 def logger(self):
226 if not self._logger:
227 self._logger = getLogger(self.name, self.version)
228 return self._logger
229
230
231class ContextAdapter(BaseLoggerAdapter):
232 warn = logging.LoggerAdapter.warning
233
234 def __init__(self, logger, project_name, version_string):
235 self.logger = logger
236 self.project = project_name
237 self.version = version_string
238
239 @property
240 def handlers(self):
241 return self.logger.handlers
242
243 def deprecated(self, msg, *args, **kwargs):
244 stdmsg = _("Deprecated: %s") % msg
245 if CONF.fatal_deprecations:
246 self.critical(stdmsg, *args, **kwargs)
247 raise DeprecatedConfig(msg=stdmsg)
248 else:
249 self.warn(stdmsg, *args, **kwargs)
250
251 def process(self, msg, kwargs):
252 if 'extra' not in kwargs:
253 kwargs['extra'] = {}
254 extra = kwargs['extra']
255
256 context = kwargs.pop('context', None)
257 if not context:
258 context = getattr(local.store, 'context', None)
259 if context:
260 extra.update(_dictify_context(context))
261
262 instance = kwargs.pop('instance', None)
263 instance_extra = ''
264 if instance:
265 instance_extra = CONF.instance_format % instance
266 else:
267 instance_uuid = kwargs.pop('instance_uuid', None)
268 if instance_uuid:
269 instance_extra = (CONF.instance_uuid_format
270 % {'uuid': instance_uuid})
271 extra.update({'instance': instance_extra})
272
273 extra.update({"project": self.project})
274 extra.update({"version": self.version})
275 extra['extra'] = extra.copy()
276 return msg, kwargs
277
278
279class JSONFormatter(logging.Formatter):
280 def __init__(self, fmt=None, datefmt=None):
281 # NOTE(jkoelker) we ignore the fmt argument, but its still there
282 # since logging.config.fileConfig passes it.
283 self.datefmt = datefmt
284
285 def formatException(self, ei, strip_newlines=True):
286 lines = traceback.format_exception(*ei)
287 if strip_newlines:
288 lines = [itertools.ifilter(
289 lambda x: x,
290 line.rstrip().splitlines()) for line in lines]
291 lines = list(itertools.chain(*lines))
292 return lines
293
294 def format(self, record):
295 message = {'message': record.getMessage(),
296 'asctime': self.formatTime(record, self.datefmt),
297 'name': record.name,
298 'msg': record.msg,
299 'args': record.args,
300 'levelname': record.levelname,
301 'levelno': record.levelno,
302 'pathname': record.pathname,
303 'filename': record.filename,
304 'module': record.module,
305 'lineno': record.lineno,
306 'funcname': record.funcName,
307 'created': record.created,
308 'msecs': record.msecs,
309 'relative_created': record.relativeCreated,
310 'thread': record.thread,
311 'thread_name': record.threadName,
312 'process_name': record.processName,
313 'process': record.process,
314 'traceback': None}
315
316 if hasattr(record, 'extra'):
317 message['extra'] = record.extra
318
319 if record.exc_info:
320 message['traceback'] = self.formatException(record.exc_info)
321
322 return jsonutils.dumps(message)
323
324
325def _create_logging_excepthook(product_name):
326 def logging_excepthook(type, value, tb):
327 extra = {}
328 if CONF.verbose:
329 extra['exc_info'] = (type, value, tb)
330 getLogger(product_name).critical(str(value), **extra)
331 return logging_excepthook
332
333
334class LogConfigError(Exception):
335
336 message = _('Error loading logging config %(log_config)s: %(err_msg)s')
337
338 def __init__(self, log_config, err_msg):
339 self.log_config = log_config
340 self.err_msg = err_msg
341
342 def __str__(self):
343 return self.message % dict(log_config=self.log_config,
344 err_msg=self.err_msg)
345
346
347def _load_log_config(log_config):
348 try:
349 logging.config.fileConfig(log_config)
350 except moves.configparser.Error as exc:
351 raise LogConfigError(log_config, str(exc))
352
353
354def setup(product_name):
355 """Setup logging."""
356 if CONF.log_config:
357 _load_log_config(CONF.log_config)
358 else:
359 _setup_logging_from_conf()
360 sys.excepthook = _create_logging_excepthook(product_name)
361
362
363def set_defaults(logging_context_format_string):
364 cfg.set_defaults(log_opts,
365 logging_context_format_string=
366 logging_context_format_string)
367
368
369def _find_facility_from_conf():
370 facility_names = logging.handlers.SysLogHandler.facility_names
371 facility = getattr(logging.handlers.SysLogHandler,
372 CONF.syslog_log_facility,
373 None)
374
375 if facility is None and CONF.syslog_log_facility in facility_names:
376 facility = facility_names.get(CONF.syslog_log_facility)
377
378 if facility is None:
379 valid_facilities = facility_names.keys()
380 consts = ['LOG_AUTH', 'LOG_AUTHPRIV', 'LOG_CRON', 'LOG_DAEMON',
381 'LOG_FTP', 'LOG_KERN', 'LOG_LPR', 'LOG_MAIL', 'LOG_NEWS',
382 'LOG_AUTH', 'LOG_SYSLOG', 'LOG_USER', 'LOG_UUCP',
383 'LOG_LOCAL0', 'LOG_LOCAL1', 'LOG_LOCAL2', 'LOG_LOCAL3',
384 'LOG_LOCAL4', 'LOG_LOCAL5', 'LOG_LOCAL6', 'LOG_LOCAL7']
385 valid_facilities.extend(consts)
386 raise TypeError(_('syslog facility must be one of: %s') %
387 ', '.join("'%s'" % fac
388 for fac in valid_facilities))
389
390 return facility
391
392
393def _setup_logging_from_conf():
394 log_root = getLogger(None).logger
395 for handler in log_root.handlers:
396 log_root.removeHandler(handler)
397
398 if CONF.use_syslog:
399 facility = _find_facility_from_conf()
400 syslog = logging.handlers.SysLogHandler(address='/dev/log',
401 facility=facility)
402 log_root.addHandler(syslog)
403
404 logpath = _get_log_file_path()
405 if logpath:
406 filelog = logging.handlers.WatchedFileHandler(logpath)
407 log_root.addHandler(filelog)
408
409 if CONF.use_stderr:
410 streamlog = ColorHandler()
411 log_root.addHandler(streamlog)
412
413 elif not CONF.log_file:
414 # pass sys.stdout as a positional argument
415 # python2.6 calls the argument strm, in 2.7 it's stream
416 streamlog = logging.StreamHandler(sys.stdout)
417 log_root.addHandler(streamlog)
418
419 if CONF.publish_errors:
420 handler = importutils.import_object(
421 "tempest.openstack.common.log_handler.PublishErrorsHandler",
422 logging.ERROR)
423 log_root.addHandler(handler)
424
425 datefmt = CONF.log_date_format
426 for handler in log_root.handlers:
427 # NOTE(alaski): CONF.log_format overrides everything currently. This
428 # should be deprecated in favor of context aware formatting.
429 if CONF.log_format:
430 handler.setFormatter(logging.Formatter(fmt=CONF.log_format,
431 datefmt=datefmt))
432 log_root.info('Deprecated: log_format is now deprecated and will '
433 'be removed in the next release')
434 else:
435 handler.setFormatter(ContextFormatter(datefmt=datefmt))
436
437 if CONF.debug:
438 log_root.setLevel(logging.DEBUG)
439 elif CONF.verbose:
440 log_root.setLevel(logging.INFO)
441 else:
442 log_root.setLevel(logging.WARNING)
443
444 for pair in CONF.default_log_levels:
445 mod, _sep, level_name = pair.partition('=')
446 level = logging.getLevelName(level_name)
447 logger = logging.getLogger(mod)
448 logger.setLevel(level)
449
450_loggers = {}
451
452
453def getLogger(name='unknown', version='unknown'):
454 if name not in _loggers:
455 _loggers[name] = ContextAdapter(logging.getLogger(name),
456 name,
457 version)
458 return _loggers[name]
459
460
461def getLazyLogger(name='unknown', version='unknown'):
462 """Returns lazy logger.
463
464 Creates a pass-through logger that does not create the real logger
465 until it is really needed and delegates all calls to the real logger
466 once it is created.
467 """
468 return LazyAdapter(name, version)
469
470
471class WritableLogger(object):
472 """A thin wrapper that responds to `write` and logs."""
473
474 def __init__(self, logger, level=logging.INFO):
475 self.logger = logger
476 self.level = level
477
478 def write(self, msg):
479 self.logger.log(self.level, msg)
480
481
482class ContextFormatter(logging.Formatter):
483 """A context.RequestContext aware formatter configured through flags.
484
485 The flags used to set format strings are: logging_context_format_string
486 and logging_default_format_string. You can also specify
487 logging_debug_format_suffix to append extra formatting if the log level is
488 debug.
489
490 For information about what variables are available for the formatter see:
491 http://docs.python.org/library/logging.html#formatter
492
493 """
494
495 def format(self, record):
496 """Uses contextstring if request_id is set, otherwise default."""
497 # NOTE(sdague): default the fancier formating params
498 # to an empty string so we don't throw an exception if
499 # they get used
500 for key in ('instance', 'color'):
501 if key not in record.__dict__:
502 record.__dict__[key] = ''
503
504 if record.__dict__.get('request_id', None):
505 self._fmt = CONF.logging_context_format_string
506 else:
507 self._fmt = CONF.logging_default_format_string
508
509 if (record.levelno == logging.DEBUG and
510 CONF.logging_debug_format_suffix):
511 self._fmt += " " + CONF.logging_debug_format_suffix
512
513 # Cache this on the record, Logger will respect our formated copy
514 if record.exc_info:
515 record.exc_text = self.formatException(record.exc_info, record)
516 return logging.Formatter.format(self, record)
517
518 def formatException(self, exc_info, record=None):
519 """Format exception output with CONF.logging_exception_prefix."""
520 if not record:
521 return logging.Formatter.formatException(self, exc_info)
522
523 stringbuffer = moves.StringIO()
524 traceback.print_exception(exc_info[0], exc_info[1], exc_info[2],
525 None, stringbuffer)
526 lines = stringbuffer.getvalue().split('\n')
527 stringbuffer.close()
528
529 if CONF.logging_exception_prefix.find('%(asctime)') != -1:
530 record.asctime = self.formatTime(record, self.datefmt)
531
532 formatted_lines = []
533 for line in lines:
534 pl = CONF.logging_exception_prefix % record.__dict__
535 fl = '%s%s' % (pl, line)
536 formatted_lines.append(fl)
537 return '\n'.join(formatted_lines)
538
539
540class ColorHandler(logging.StreamHandler):
541 LEVEL_COLORS = {
542 logging.DEBUG: '\033[00;32m', # GREEN
543 logging.INFO: '\033[00;36m', # CYAN
544 logging.AUDIT: '\033[01;36m', # BOLD CYAN
545 logging.WARN: '\033[01;33m', # BOLD YELLOW
546 logging.ERROR: '\033[01;31m', # BOLD RED
547 logging.CRITICAL: '\033[01;31m', # BOLD RED
548 }
549
550 def format(self, record):
551 record.color = self.LEVEL_COLORS[record.levelno]
552 return logging.StreamHandler.format(self, record)
553
554
555class DeprecatedConfig(Exception):
556 message = _("Fatal call to deprecated config: %(msg)s")
557
558 def __init__(self, msg):
559 super(Exception, self).__init__(self.message % dict(msg=msg))