34
20
Output to stderr depends on the mode chosen by the user. By default, messages
35
21
of info and above are sent out, which results in progress messages such as the
36
list of files processed by add and commit. In debug mode, stderr gets debug messages too.
22
list of files processed by add and commit. In quiet mode, only warnings and
23
above are shown. In debug mode, stderr gets debug messages too.
38
25
Errors that terminate an operation are generally passed back as exceptions;
39
26
others may be just emitted as messages.
41
28
Exceptions are reported in a brief form to stderr so as not to look scary.
42
29
BzrErrors are required to be able to format themselves into a properly
43
explanatory message. This is not true for builtin exceptions such as
30
explanatory message. This is not true for builtin excexceptions such as
44
31
KeyError, which typically just str to "0". They're printed in a different
35
# TODO: in debug mode, stderr should get full tracebacks and also
36
# debug messages. (Is this really needed?)
48
38
# FIXME: Unfortunately it turns out that python's logging module
49
39
# is quite expensive, even when the message is not printed by any handlers.
50
40
# We should perhaps change back to just simply doing it here.
52
# On the other hand, as of 1.2 we generally only call the mutter() statement
53
# if (according to debug_flags) we actually intend to write it. So the
54
# increased cost of logging.py is not so bad, and we could standardize on
62
from bzrlib.lazy_import import lazy_import
63
lazy_import(globals(), """
64
from cStringIO import StringIO
73
from bzrlib.symbol_versioning import (
78
lazy_import(globals(), """
88
# global verbosity for bzrlib; controls the log level for stderr; 0=normal; <0
89
# is quiet; >0 is verbose.
92
# File-like object where mutter/debug output is currently sent. Can be
93
# changed by _push_log_file etc. This is directly manipulated by some
94
# external code; maybe there should be functions to do that more precisely
95
# than push/pop_log_file.
48
from bzrlib.errors import BzrError, BzrNewError
52
_stderr_handler = None
98
# Absolute path for ~/.bzr.log. Not changed even if the log/trace output is
99
# redirected elsewhere. Used to show the location in --version.
100
_bzr_log_filename = None
102
# The time the first message was written to the trace file, so that we can
103
# show relative times since startup.
104
_bzr_log_start_time = bzrlib._start_time
107
# held in a global for quick reference
58
class QuietFormatter(logging.Formatter):
59
"""Formatter that supresses the details of errors.
61
This is used by default on stderr so as not to scare the user.
63
# At first I tried overriding formatException to suppress the
64
# exception details, but that has global effect: no loggers
65
# can get the exception details is we suppress them here.
67
def format(self, record):
68
if record.levelno >= logging.WARNING:
69
s = 'bzr: ' + record.levelname + ': '
72
s += record.getMessage()
74
s += '\n' + format_exception_short(record.exc_info)
77
# configure convenient aliases for output routines
108
79
_bzr_logger = logging.getLogger('bzr')
111
def note(*args, **kwargs):
112
"""Output a note to the user.
114
Takes the same parameters as logging.info.
118
# FIXME: clearing the ui and then going through the abstract logging
119
# framework is whack; we should probably have a logging Handler that
120
# deals with terminal output if needed.
121
ui.ui_factory.clear_term()
122
_bzr_logger.info(*args, **kwargs)
125
def warning(*args, **kwargs):
126
ui.ui_factory.clear_term()
127
_bzr_logger.warning(*args, **kwargs)
130
@deprecated_function(deprecated_in((2, 1, 0)))
131
def info(*args, **kwargs):
132
"""Deprecated: use trace.note instead."""
133
note(*args, **kwargs)
136
@deprecated_function(deprecated_in((2, 1, 0)))
137
def log_error(*args, **kwargs):
138
"""Deprecated: use bzrlib.trace.show_error instead"""
139
_bzr_logger.error(*args, **kwargs)
142
@deprecated_function(deprecated_in((2, 1, 0)))
143
def error(*args, **kwargs):
144
"""Deprecated: use bzrlib.trace.show_error instead"""
145
_bzr_logger.error(*args, **kwargs)
148
def show_error(*args, **kwargs):
149
"""Show an error message to the user.
151
Don't use this for exceptions, use report_exception instead.
153
_bzr_logger.error(*args, **kwargs)
81
info = note = _bzr_logger.info
82
warning = _bzr_logger.warning
83
log_error = _bzr_logger.error
84
error = _bzr_logger.error
156
87
def mutter(fmt, *args):
157
88
if _trace_file is None:
159
# XXX: Don't check this every time; instead anyone who closes the file
160
# ought to deregister it. We can tolerate None.
161
if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
90
if hasattr(_trace_file, 'closed') and _trace_file.closed:
164
if isinstance(fmt, unicode):
165
fmt = fmt.encode('utf8')
168
# It seems that if we do ascii % (unicode, ascii) we can
169
# get a unicode cannot encode ascii error, so make sure that "fmt"
170
# is a unicode string
173
if isinstance(arg, unicode):
174
arg = arg.encode('utf8')
175
real_args.append(arg)
176
out = fmt % tuple(real_args)
180
timestamp = '%0.3f ' % (now - _bzr_log_start_time,)
181
out = timestamp + out + '\n'
97
if isinstance(out, unicode):
98
out = out.encode('utf-8')
182
99
_trace_file.write(out)
183
# there's no explicit flushing; the file is typically line buffered.
186
def mutter_callsite(stacklevel, fmt, *args):
187
"""Perform a mutter of fmt and args, logging the call trace.
189
:param stacklevel: The number of frames to show. None will show all
191
:param fmt: The format string to pass to mutter.
192
:param args: A list of substitution variables.
195
if stacklevel is None:
198
limit = stacklevel + 1
199
traceback.print_stack(limit=limit, file=outf)
200
formatted_lines = outf.getvalue().splitlines()
201
formatted_stack = '\n'.join(formatted_lines[:-2])
202
mutter(fmt + "\nCalled from:\n%s", *(args + (formatted_stack,)))
205
103
def _rollover_trace_maybe(trace_fname):
209
107
if size <= 4 << 20:
211
109
old_fname = trace_fname + '.old'
212
osutils.rename(trace_fname, old_fname)
110
from osutils import rename
111
rename(trace_fname, old_fname)
217
def _get_bzr_log_filename():
218
bzr_log = os.environ.get('BZR_LOG')
221
home = os.environ.get('BZR_HOME')
223
if sys.platform == 'win32':
224
from bzrlib import win32utils
225
home = win32utils.get_home_location()
227
home = os.path.expanduser('~')
228
return os.path.join(home, '.bzr.log')
232
"""Open the .bzr.log trace file.
234
If the log is more than a particular length, the old file is renamed to
235
.bzr.log.old and a new file is started. Otherwise, we append to the
238
This sets the global _bzr_log_filename.
240
global _bzr_log_filename
242
def _open_or_create_log_file(filename):
243
"""Open existing log file, or create with ownership and permissions
245
It inherits the ownership and permissions (masked by umask) from
246
the containing directory to cope better with being run under sudo
247
with $HOME still set to the user's homedir.
249
flags = os.O_WRONLY | os.O_APPEND | osutils.O_TEXT
252
fd = os.open(filename, flags)
255
if e.errno != errno.ENOENT:
258
fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0666)
260
if e.errno != errno.EEXIST:
263
osutils.copy_ownership_from_path(filename)
265
return os.fdopen(fd, 'at', 0) # unbuffered
268
_bzr_log_filename = _get_bzr_log_filename()
269
_rollover_trace_maybe(_bzr_log_filename)
116
def open_tracefile(tracefilename='~/.bzr.log'):
117
# Messages are always written to here, so that we have some
118
# information if something goes wrong. In a future version this
119
# file will be removed on successful completion.
120
global _file_handler, _bzr_log_file
123
trace_fname = os.path.join(os.path.expanduser(tracefilename))
124
_rollover_trace_maybe(trace_fname)
271
bzr_log_file = _open_or_create_log_file(_bzr_log_filename)
272
bzr_log_file.write('\n')
273
if bzr_log_file.tell() <= 2:
274
bzr_log_file.write("this is a debug log for diagnosing/reporting problems in bzr\n")
275
bzr_log_file.write("you can delete or truncate this file, or include sections in\n")
276
bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
280
except EnvironmentError, e:
281
# If we are failing to open the log, then most likely logging has not
282
# been set up yet. So we just write to stderr rather than using
283
# 'warning()'. If we using warning(), users get the unhelpful 'no
284
# handlers registered for "bzr"' when something goes wrong on the
285
# server. (bug #503886)
286
sys.stderr.write("failed to open trace file: %s\n" % (e,))
287
# TODO: What should happen if we fail to open the trace file? Maybe the
288
# objects should be pointed at /dev/null or the equivalent? Currently
289
# returns None which will cause failures later.
293
def enable_default_logging():
294
"""Configure default logging: messages to stderr and debug to .bzr.log
296
This should only be called once per process.
298
Non-command-line programs embedding bzrlib do not need to call this. They
299
can instead either pass a file to _push_log_file, or act directly on
300
logging.getLogger("bzr").
302
Output can be redirected away by calling _push_log_file.
304
:return: A memento from push_log_file for restoring the log state.
306
start_time = osutils.format_local_date(_bzr_log_start_time,
308
bzr_log_file = _open_bzr_log()
309
if bzr_log_file is not None:
310
bzr_log_file.write(start_time.encode('utf-8') + '\n')
311
memento = push_log_file(bzr_log_file,
312
r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
313
r'%Y-%m-%d %H:%M:%S')
314
# after hooking output into bzr_log, we also need to attach a stderr
315
# handler, writing only at level info and with encoding
316
stderr_handler = EncodedStreamHandler(sys.stderr,
317
osutils.get_terminal_encoding(), 'replace', level=logging.INFO)
318
logging.getLogger('bzr').addHandler(stderr_handler)
322
def push_log_file(to_file, log_format=None, date_format=None):
323
"""Intercept log and trace messages and send them to a file.
325
:param to_file: A file-like object to which messages will be sent.
327
:returns: A memento that should be passed to _pop_log_file to restore the
328
previously active logging.
332
new_handler = EncodedStreamHandler(to_file, "utf-8", level=logging.DEBUG)
333
if log_format is None:
334
log_format = '%(levelname)8s %(message)s'
335
new_handler.setFormatter(logging.Formatter(log_format, date_format))
336
# save and remove any existing log handlers
337
bzr_logger = logging.getLogger('bzr')
338
old_handlers = bzr_logger.handlers[:]
339
del bzr_logger.handlers[:]
340
# set that as the default logger
341
bzr_logger.addHandler(new_handler)
342
bzr_logger.setLevel(logging.DEBUG)
343
# TODO: check if any changes are needed to the root logger
345
# TODO: also probably need to save and restore the level on bzr_logger.
346
# but maybe we can avoid setting the logger level altogether, and just set
347
# the level on the handler?
349
# save the old trace file
350
old_trace_file = _trace_file
351
# send traces to the new one
352
_trace_file = to_file
353
result = new_handler, _trace_file
354
return ('log_memento', old_handlers, new_handler, old_trace_file, to_file)
357
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
358
"""Undo changes to logging/tracing done by _push_log_file.
360
This flushes, but does not close the trace file (so that anything that was
363
Takes the memento returned from _push_log_file."""
365
_trace_file = old_trace_file
366
bzr_logger = logging.getLogger('bzr')
367
bzr_logger.removeHandler(new_handler)
368
# must be closed, otherwise logging will try to close it at exit, and the
369
# file will likely already be closed underneath.
371
bzr_logger.handlers = old_handlers
372
if new_trace_file is not None:
373
new_trace_file.flush()
127
tf = codecs.open(trace_fname, 'at', 'utf8', buffering=LINE_BUFFERED)
130
tf.write("\nthis is a debug log for diagnosing/reporting problems in bzr\n")
131
tf.write("you can delete or truncate this file, or include sections in\n")
132
tf.write("bug reports to bazaar-ng@lists.canonical.com\n\n")
133
_file_handler = logging.StreamHandler(tf)
134
fmt = r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s'
135
datefmt = r'%a %H:%M:%S'
136
_file_handler.setFormatter(logging.Formatter(fmt, datefmt))
137
_file_handler.setLevel(logging.DEBUG)
138
logging.getLogger('').addHandler(_file_handler)
140
warning("failed to open trace file: %s" % (e))
143
def log_startup(argv):
144
debug('\n\nbzr %s invoked on python %s (%s)',
146
'.'.join(map(str, sys.version_info)),
148
debug(' arguments: %r', argv)
149
debug(' working dir: %r', os.getcwdu())
152
def log_exception(msg=None):
153
"""Log the last exception to stderr and the trace file.
155
The exception string representation is used as the error
156
summary, unless msg is given.
161
exc_str = format_exception_short(sys.exc_info())
163
log_exception_quietly()
376
166
def log_exception_quietly():
377
167
"""Log the last exception to the trace file only.
379
Used for exceptions that occur internally and that may be
380
interesting to developers but not to users. For example,
169
Used for exceptions that occur internally and that may be
170
interesting to developers but not to users. For example,
381
171
errors loading plugins.
383
mutter(traceback.format_exc())
386
def set_verbosity_level(level):
387
"""Set the verbosity level.
389
:param level: -ve for quiet, 0 for normal, +ve for verbose
391
global _verbosity_level
392
_verbosity_level = level
393
_update_logging_level(level < 0)
394
ui.ui_factory.be_quiet(level < 0)
397
def get_verbosity_level():
398
"""Get the verbosity level.
400
See set_verbosity_level() for values.
402
return _verbosity_level
174
debug(traceback.format_exc())
177
def enable_default_logging():
178
"""Configure default logging to stderr and .bzr.log"""
179
# FIXME: if this is run twice, things get confused
180
global _stderr_handler, _file_handler, _trace_file, _bzr_log_file
181
_stderr_handler = logging.StreamHandler()
182
_stderr_handler.setFormatter(QuietFormatter())
183
logging.getLogger('').addHandler(_stderr_handler)
184
_stderr_handler.setLevel(logging.INFO)
185
if not _file_handler:
187
_trace_file = _bzr_log_file
189
_file_handler.setLevel(logging.DEBUG)
190
_bzr_logger.setLevel(logging.DEBUG)
405
194
def be_quiet(quiet=True):
407
set_verbosity_level(-1)
409
set_verbosity_level(0)
412
def _update_logging_level(quiet=True):
413
"""Hide INFO messages if quiet."""
415
_bzr_logger.setLevel(logging.WARNING)
417
_bzr_logger.setLevel(logging.INFO)
195
global _stderr_handler, _stderr_quiet
197
_stderr_quiet = quiet
199
_stderr_handler.setLevel(logging.WARNING)
201
_stderr_handler.setLevel(logging.INFO)
421
"""Is the verbosity level negative?"""
422
return _verbosity_level < 0
426
"""Is the verbosity level positive?"""
427
return _verbosity_level > 0
430
def debug_memory(message='', short=True):
431
"""Write out a memory dump."""
432
if sys.platform == 'win32':
433
from bzrlib import win32utils
434
win32utils.debug_memory_win32api(message=message, short=short)
436
_debug_memory_proc(message=message, short=short)
439
_short_fields = ('VmPeak', 'VmSize', 'VmRSS')
441
def _debug_memory_proc(message='', short=True):
443
status_file = file('/proc/%s/status' % os.getpid(), 'rb')
447
status = status_file.read()
452
for line in status.splitlines():
456
for field in _short_fields:
457
if line.startswith(field):
461
def _dump_memory_usage(err_file):
464
fd, name = tempfile.mkstemp(prefix="bzr_memdump", suffix=".json")
465
dump_file = os.fdopen(fd, 'w')
466
from meliae import scanner
467
scanner.dump_gc_objects(dump_file)
468
err_file.write("Memory dumped to %s\n" % name)
470
err_file.write("Dumping memory requires meliae module.\n")
471
log_exception_quietly()
473
err_file.write("Exception while dumping memory.\n")
474
log_exception_quietly()
476
if dump_file is not None:
482
def _qualified_exception_name(eclass, unqualified_bzrlib_errors=False):
483
"""Give name of error class including module for non-builtin exceptions
485
If `unqualified_bzrlib_errors` is True, errors specific to bzrlib will
486
also omit the module prefix.
488
class_name = eclass.__name__
489
module_name = eclass.__module__
490
if module_name in ("exceptions", "__main__") or (
491
unqualified_bzrlib_errors and module_name == "bzrlib.errors"):
493
return "%s.%s" % (module_name, class_name)
496
def report_exception(exc_info, err_file):
497
"""Report an exception to err_file (typically stderr) and to .bzr.log.
499
This will show either a full traceback or a short message as appropriate.
501
:return: The appropriate exit code for this error.
503
# Log the full traceback to ~/.bzr.log
504
log_exception_quietly()
505
if 'error' in debug.debug_flags:
506
print_exception(exc_info, err_file)
507
return errors.EXIT_ERROR
508
exc_type, exc_object, exc_tb = exc_info
509
if (isinstance(exc_object, IOError)
510
and getattr(exc_object, 'errno', None) == errno.EPIPE):
511
err_file.write("bzr: broken pipe\n")
512
return errors.EXIT_ERROR
513
elif isinstance(exc_object, KeyboardInterrupt):
514
err_file.write("bzr: interrupted\n")
515
return errors.EXIT_ERROR
516
elif isinstance(exc_object, MemoryError):
517
err_file.write("bzr: out of memory\n")
518
if 'mem_dump' in debug.debug_flags:
519
_dump_memory_usage(err_file)
521
err_file.write("Use -Dmem_dump to dump memory to a file.\n")
522
return errors.EXIT_ERROR
523
elif isinstance(exc_object, ImportError) \
524
and str(exc_object).startswith("No module named "):
525
report_user_error(exc_info, err_file,
526
'You may need to install this Python library separately.')
527
return errors.EXIT_ERROR
528
elif not getattr(exc_object, 'internal_error', True):
529
report_user_error(exc_info, err_file)
530
return errors.EXIT_ERROR
531
elif isinstance(exc_object, (OSError, IOError)) or (
532
# GZ 2010-05-20: Like (exc_type is pywintypes.error) but avoid import
533
exc_type.__name__ == "error" and exc_type.__module__ == "pywintypes"):
534
# Might be nice to catch all of these and show them as something more
535
# specific, but there are too many cases at the moment.
536
report_user_error(exc_info, err_file)
537
return errors.EXIT_ERROR
539
report_bug(exc_info, err_file)
540
return errors.EXIT_INTERNAL_ERROR
543
def print_exception(exc_info, err_file):
544
exc_type, exc_object, exc_tb = exc_info
545
err_file.write("bzr: ERROR: %s.%s: %s\n" % (
546
exc_type.__module__, exc_type.__name__, exc_object))
548
traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
551
# TODO: Should these be specially encoding the output?
552
def report_user_error(exc_info, err_file, advice=None):
553
"""Report to err_file an error that's not an internal error.
555
These don't get a traceback unless -Derror was given.
557
:param exc_info: 3-tuple from sys.exc_info()
558
:param advice: Extra advice to the user to be printed following the
561
err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
563
err_file.write("%s\n" % (advice,))
566
def report_bug(exc_info, err_file):
567
"""Report an exception that probably indicates a bug in bzr"""
568
from bzrlib.crash import report_bug
569
report_bug(exc_info, err_file)
572
def _flush_stdout_stderr():
573
# called from the bzrlib library finalizer returned by bzrlib.initialize()
579
if e.errno in [errno.EINVAL, errno.EPIPE]:
586
# called from the bzrlib library finalizer returned by bzrlib.initialize()
592
class EncodedStreamHandler(logging.Handler):
593
"""Robustly write logging events to a stream using the specified encoding
595
Messages are expected to be formatted to unicode, but UTF-8 byte strings
596
are also accepted. An error during formatting or a str message in another
597
encoding will be quitely noted as an error in the Bazaar log file.
599
The stream is not closed so sys.stdout or sys.stderr may be passed.
602
def __init__(self, stream, encoding=None, errors='strict', level=0):
603
logging.Handler.__init__(self, level)
606
encoding = getattr(stream, "encoding", "ascii")
607
self.encoding = encoding
611
flush = getattr(self.stream, "flush", None)
612
if flush is not None:
615
def emit(self, record):
617
line = self.format(record)
618
if not isinstance(line, unicode):
619
line = line.decode("utf-8")
620
self.stream.write(line.encode(self.encoding, self.errors) + "\n")
622
log_exception_quietly()
623
# Try saving the details that would have been logged in some form
624
msg = args = "<Unformattable>"
626
msg = repr(record.msg).encode("ascii")
627
args = repr(record.args).encode("ascii")
630
# Using mutter() bypasses the logging module and writes directly
631
# to the file so there's no danger of getting into a loop here.
632
mutter("Logging record unformattable: %s %% %s", msg, args)
635
class Config(object):
636
"""Configuration of message tracing in bzrlib.
638
This implements the context manager protocol and should manage any global
639
variables still used. The default config used is DefaultConfig, but
640
embedded uses of bzrlib may wish to use a custom manager.
644
return self # This is bound to the 'as' clause in a with statement.
646
def __exit__(self, exc_type, exc_val, exc_tb):
647
return False # propogate exceptions.
650
class DefaultConfig(Config):
651
"""A default configuration for tracing of messages in bzrlib.
653
This implements the context manager protocol.
657
self._original_filename = _bzr_log_filename
658
self._original_state = enable_default_logging()
659
return self # This is bound to the 'as' clause in a with statement.
661
def __exit__(self, exc_type, exc_val, exc_tb):
662
pop_log_file(self._original_state)
663
global _bzr_log_filename
664
_bzr_log_filename = self._original_filename
665
return False # propogate exceptions.
209
def disable_default_logging():
210
"""Turn off default log handlers.
212
This is intended to be used by the test framework, which doesn't
213
want leakage from the code-under-test into the main logs.
216
l = logging.getLogger('')
217
l.removeHandler(_stderr_handler)
219
l.removeHandler(_file_handler)
223
def enable_test_log(to_file):
224
"""Redirect logging to a temporary file for a test"""
225
disable_default_logging()
226
global _test_log_hdlr, _trace_file
227
hdlr = logging.StreamHandler(to_file)
228
hdlr.setLevel(logging.DEBUG)
229
hdlr.setFormatter(logging.Formatter('%(levelname)8s %(message)s'))
230
_bzr_logger.addHandler(hdlr)
231
_bzr_logger.setLevel(logging.DEBUG)
232
_test_log_hdlr = hdlr
233
_trace_file = to_file
236
def disable_test_log():
237
_bzr_logger.removeHandler(_test_log_hdlr)
239
enable_default_logging()
242
def format_exception_short(exc_info):
243
"""Make a short string form of an exception.
245
This is used for display to stderr. It specially handles exception
246
classes without useful string methods.
248
The result has no trailing newline.
250
exc_info - typically an exception from sys.exc_info()
252
exc_type, exc_object, exc_tb = exc_info
255
return '(no exception)'
256
if isinstance(exc_object, (BzrError, BzrNewError)):
257
return str(exc_object)
260
tb = traceback.extract_tb(exc_tb)
261
msg = '%s: %s' % (exc_type, exc_object)
265
msg += '\n at %s line %d\n in %s' % (tb[-1][:3])
267
except Exception, formatting_exc:
268
# XXX: is this really better than just letting it run up?
269
return '(error formatting exception of type %s: %s)' \
270
% (exc_type, formatting_exc)
added
removed
bzrlib/trace.py
