49
49
# FIXME: Unfortunately it turns out that python's logging module
50
50
# is quite expensive, even when the message is not printed by any handlers.
51
51
# We should perhaps change back to just simply doing it here.
53
# On the other hand, as of 1.2 we generally only call the mutter() statement
54
# if (according to debug_flags) we actually intend to write it. So the
55
# increased cost of logging.py is not so bad, and we could standardize on
65
from bzrlib.lazy_import import lazy_import
66
lazy_import(globals(), """
67
from cStringIO import StringIO
60
from bzrlib.errors import BzrError, BzrNewError
61
from bzrlib.symbol_versioning import (deprecated_function,
66
_stderr_handler = None
75
lazy_import(globals(), """
86
# global verbosity for bzrlib; controls the log level for stderr; 0=normal; <0
87
# is quiet; >0 is verbose.
90
# File-like object where mutter/debug output is currently sent. Can be
91
# changed by _push_log_file etc. This is directly manipulated by some
92
# external code; maybe there should be functions to do that more precisely
93
# than push/pop_log_file.
73
# configure convenient aliases for output routines
96
# Absolute path for ~/.bzr.log. Not changed even if the log/trace output is
97
# redirected elsewhere. Used to show the location in --version.
98
_bzr_log_filename = None
100
# The time the first message was written to the trace file, so that we can
101
# show relative times since startup.
102
_bzr_log_start_time = bzrlib._start_time
105
# held in a global for quick reference
75
106
_bzr_logger = logging.getLogger('bzr')
77
109
def note(*args, **kwargs):
78
110
# FIXME note always emits utf-8, regardless of the terminal encoding
112
# FIXME: clearing the ui and then going through the abstract logging
113
# framework is whack; we should probably have a logging Handler that
114
# deals with terminal output if needed.
80
116
bzrlib.ui.ui_factory.clear_term()
81
117
_bzr_logger.info(*args, **kwargs)
83
120
def warning(*args, **kwargs):
85
122
bzrlib.ui.ui_factory.clear_term()
86
123
_bzr_logger.warning(*args, **kwargs)
126
# configure convenient aliases for output routines
128
# TODO: deprecate them, have one name for each.
89
130
log_error = _bzr_logger.error
90
131
error = _bzr_logger.error
93
134
def mutter(fmt, *args):
94
135
if _trace_file is None:
96
if hasattr(_trace_file, 'closed') and _trace_file.closed:
137
if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
140
if isinstance(fmt, unicode):
141
fmt = fmt.encode('utf8')
99
144
# It seems that if we do ascii % (unicode, ascii) we can
100
145
# get a unicode cannot encode ascii error, so make sure that "fmt"
101
146
# is a unicode string
102
out = unicode(fmt) % args
149
if isinstance(arg, unicode):
150
arg = arg.encode('utf8')
151
real_args.append(arg)
152
out = fmt % tuple(real_args)
107
_trace_file.write(out)
108
except UnicodeError, e:
109
warning('UnicodeError: %s', e)
110
_trace_file.write(repr(out))
111
# TODO: jam 20051227 Consider flushing the trace file to help debugging
155
timestamp = '%0.3f ' % (time.time() - _bzr_log_start_time,)
156
out = timestamp + out + '\n'
157
_trace_file.write(out)
158
# no need to flush here, the trace file is now linebuffered when it's
162
def mutter_callsite(stacklevel, fmt, *args):
163
"""Perform a mutter of fmt and args, logging the call trace.
165
:param stacklevel: The number of frames to show. None will show all
167
:param fmt: The format string to pass to mutter.
168
:param args: A list of substitution variables.
171
if stacklevel is None:
174
limit = stacklevel + 1
175
traceback.print_stack(limit=limit, file=outf)
176
formatted_lines = outf.getvalue().splitlines()
177
formatted_stack = '\n'.join(formatted_lines[:-2])
178
mutter(fmt + "\nCalled from:\n%s", *(args + (formatted_stack,)))
116
181
def _rollover_trace_maybe(trace_fname):
120
185
if size <= 4 << 20:
122
187
old_fname = trace_fname + '.old'
123
from osutils import rename
124
rename(trace_fname, old_fname)
188
osutils.rename(trace_fname, old_fname)
129
def open_tracefile(tracefilename='~/.bzr.log'):
130
# Messages are always written to here, so that we have some
131
# information if something goes wrong. In a future version this
132
# file will be removed on successful completion.
133
global _file_handler, _bzr_log_file
136
trace_fname = os.path.join(os.path.expanduser(tracefilename))
137
_rollover_trace_maybe(trace_fname)
193
def _get_bzr_log_filename():
194
bzr_log = os.environ.get('BZR_LOG')
197
home = os.environ.get('BZR_HOME')
199
if sys.platform == 'win32':
200
from bzrlib import win32utils
201
home = win32utils.get_home_location()
203
home = os.path.expanduser('~')
204
return os.path.join(home, '.bzr.log')
208
"""Open the .bzr.log trace file.
210
If the log is more than a particular length, the old file is renamed to
211
.bzr.log.old and a new file is started. Otherwise, we append to the
214
This sets the global _bzr_log_filename.
216
global _bzr_log_filename
217
_bzr_log_filename = _get_bzr_log_filename()
218
_rollover_trace_maybe(_bzr_log_filename)
140
tf = codecs.open(trace_fname, 'at', 'utf8', buffering=LINE_BUFFERED)
143
tf.write("\nthis is a debug log for diagnosing/reporting problems in bzr\n")
144
tf.write("you can delete or truncate this file, or include sections in\n")
145
tf.write("bug reports to bazaar-ng@lists.canonical.com\n\n")
146
_file_handler = logging.StreamHandler(tf)
147
fmt = r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s'
148
datefmt = r'%a %H:%M:%S'
149
_file_handler.setFormatter(logging.Formatter(fmt, datefmt))
150
_file_handler.setLevel(logging.DEBUG)
151
logging.getLogger('').addHandler(_file_handler)
220
bzr_log_file = open(_bzr_log_filename, 'at', 1) # line buffered
221
# bzr_log_file.tell() on windows always return 0 until some writing done
222
bzr_log_file.write('\n')
223
if bzr_log_file.tell() <= 2:
224
bzr_log_file.write("this is a debug log for diagnosing/reporting problems in bzr\n")
225
bzr_log_file.write("you can delete or truncate this file, or include sections in\n")
226
bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
152
228
except IOError, e:
153
229
warning("failed to open trace file: %s" % (e))
156
@deprecated_function(zero_nine)
157
def log_exception(msg=None):
158
"""Log the last exception to stderr and the trace file.
160
The exception string representation is used as the error
161
summary, unless msg is given.
166
exc_str = format_exception_short(sys.exc_info())
168
log_exception_quietly()
230
# TODO: What should happen if we fail to open the trace file? Maybe the
231
# objects should be pointed at /dev/null or the equivalent? Currently
232
# returns None which will cause failures later.
235
def enable_default_logging():
236
"""Configure default logging: messages to stderr and debug to .bzr.log
238
This should only be called once per process.
240
Non-command-line programs embedding bzrlib do not need to call this. They
241
can instead either pass a file to _push_log_file, or act directly on
242
logging.getLogger("bzr").
244
Output can be redirected away by calling _push_log_file.
246
# create encoded wrapper around stderr
247
bzr_log_file = _open_bzr_log()
248
push_log_file(bzr_log_file,
249
r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
250
r'%Y-%m-%d %H:%M:%S')
251
# after hooking output into bzr_log, we also need to attach a stderr
252
# handler, writing only at level info and with encoding
253
writer_factory = codecs.getwriter(osutils.get_terminal_encoding())
254
encoded_stderr = writer_factory(sys.stderr, errors='replace')
255
stderr_handler = logging.StreamHandler(encoded_stderr)
256
stderr_handler.setLevel(logging.INFO)
257
logging.getLogger('bzr').addHandler(stderr_handler)
260
def push_log_file(to_file, log_format=None, date_format=None):
261
"""Intercept log and trace messages and send them to a file.
263
:param to_file: A file-like object to which messages will be sent.
265
:returns: A memento that should be passed to _pop_log_file to restore the
266
previously active logging.
270
new_handler = logging.StreamHandler(to_file)
271
new_handler.setLevel(logging.DEBUG)
272
if log_format is None:
273
log_format = '%(levelname)8s %(message)s'
274
new_handler.setFormatter(logging.Formatter(log_format, date_format))
275
# save and remove any existing log handlers
276
bzr_logger = logging.getLogger('bzr')
277
old_handlers = bzr_logger.handlers[:]
278
del bzr_logger.handlers[:]
279
# set that as the default logger
280
bzr_logger.addHandler(new_handler)
281
bzr_logger.setLevel(logging.DEBUG)
282
# TODO: check if any changes are needed to the root logger
284
# TODO: also probably need to save and restore the level on bzr_logger.
285
# but maybe we can avoid setting the logger level altogether, and just set
286
# the level on the handler?
288
# save the old trace file
289
old_trace_file = _trace_file
290
# send traces to the new one
291
_trace_file = to_file
292
result = new_handler, _trace_file
293
return ('log_memento', old_handlers, new_handler, old_trace_file, to_file)
296
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
297
"""Undo changes to logging/tracing done by _push_log_file.
299
This flushes, but does not close the trace file.
301
Takes the memento returned from _push_log_file."""
303
_trace_file = old_trace_file
304
bzr_logger = logging.getLogger('bzr')
305
bzr_logger.removeHandler(new_handler)
306
# must be closed, otherwise logging will try to close it atexit, and the
307
# file will likely already be closed underneath.
309
bzr_logger.handlers = old_handlers
310
new_trace_file.flush()
313
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
314
def enable_test_log(to_file):
315
"""Redirect logging to a temporary file for a test
317
:returns: an opaque reference that should be passed to disable_test_log
318
after the test completes.
320
return push_log_file(to_file)
323
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
324
def disable_test_log(memento):
325
return pop_log_file(memento)
171
328
def log_exception_quietly():
175
332
interesting to developers but not to users. For example,
176
333
errors loading plugins.
179
debug(traceback.format_exc())
182
def enable_default_logging():
183
"""Configure default logging to stderr and .bzr.log"""
184
# FIXME: if this is run twice, things get confused
185
global _stderr_handler, _file_handler, _trace_file, _bzr_log_file
186
_stderr_handler = logging.StreamHandler()
187
logging.getLogger('').addHandler(_stderr_handler)
188
_stderr_handler.setLevel(logging.INFO)
189
if not _file_handler:
191
_trace_file = _bzr_log_file
193
_file_handler.setLevel(logging.DEBUG)
194
_bzr_logger.setLevel(logging.DEBUG)
335
mutter(traceback.format_exc())
338
def set_verbosity_level(level):
339
"""Set the verbosity level.
341
:param level: -ve for quiet, 0 for normal, +ve for verbose
343
global _verbosity_level
344
_verbosity_level = level
345
_update_logging_level(level < 0)
348
def get_verbosity_level():
349
"""Get the verbosity level.
351
See set_verbosity_level() for values.
353
return _verbosity_level
197
356
def be_quiet(quiet=True):
198
global _stderr_handler, _stderr_quiet
200
_stderr_quiet = quiet
202
_stderr_handler.setLevel(logging.WARNING)
204
_stderr_handler.setLevel(logging.INFO)
357
# Perhaps this could be deprecated now ...
359
set_verbosity_level(-1)
361
set_verbosity_level(0)
364
def _update_logging_level(quiet=True):
365
"""Hide INFO messages if quiet."""
367
_bzr_logger.setLevel(logging.WARNING)
369
_bzr_logger.setLevel(logging.INFO)
373
"""Is the verbosity level negative?"""
374
return _verbosity_level < 0
378
"""Is the verbosity level positive?"""
379
return _verbosity_level > 0
382
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
212
383
def disable_default_logging():
213
384
"""Turn off default log handlers.
215
This is intended to be used by the test framework, which doesn't
216
want leakage from the code-under-test into the main logs.
219
l = logging.getLogger('')
220
l.removeHandler(_stderr_handler)
222
l.removeHandler(_file_handler)
226
def enable_test_log(to_file):
227
"""Redirect logging to a temporary file for a test
229
returns an opaque reference that should be passed to disable_test_log
230
after the test completes.
232
disable_default_logging()
235
hdlr = logging.StreamHandler(to_file)
236
hdlr.setLevel(logging.DEBUG)
237
hdlr.setFormatter(logging.Formatter('%(levelname)8s %(message)s'))
238
_bzr_logger.addHandler(hdlr)
239
_bzr_logger.setLevel(logging.DEBUG)
240
result = hdlr, _trace_file, _trace_depth
241
_trace_file = to_file
246
def disable_test_log((test_log_hdlr, old_trace_file, old_trace_depth)):
247
_bzr_logger.removeHandler(test_log_hdlr)
248
test_log_hdlr.close()
251
_trace_file = old_trace_file
252
_trace_depth = old_trace_depth
254
enable_default_logging()
386
Don't call this method, use _push_log_file and _pop_log_file instead.
257
391
def report_exception(exc_info, err_file):
392
"""Report an exception to err_file (typically stderr) and to .bzr.log.
394
This will show either a full traceback or a short message as appropriate.
396
:return: The appropriate exit code for this error.
258
398
exc_type, exc_object, exc_tb = exc_info
259
399
# Log the full traceback to ~/.bzr.log
260
400
log_exception_quietly()
261
401
if (isinstance(exc_object, IOError)
262
402
and getattr(exc_object, 'errno', None) == errno.EPIPE):
263
print >>err_file, "bzr: broken pipe"
403
err_file.write("bzr: broken pipe\n")
404
return errors.EXIT_ERROR
264
405
elif isinstance(exc_object, KeyboardInterrupt):
265
print >>err_file, "bzr: interrupted"
266
elif getattr(exc_object, 'is_user_error', False):
406
err_file.write("bzr: interrupted\n")
407
return errors.EXIT_ERROR
408
elif isinstance(exc_object, ImportError) \
409
and str(exc_object).startswith("No module named "):
410
report_user_error(exc_info, err_file,
411
'You may need to install this Python library separately.')
412
return errors.EXIT_ERROR
413
elif not getattr(exc_object, 'internal_error', True):
267
414
report_user_error(exc_info, err_file)
415
return errors.EXIT_ERROR
268
416
elif isinstance(exc_object, (OSError, IOError)):
269
417
# Might be nice to catch all of these and show them as something more
270
418
# specific, but there are too many cases at the moment.
271
419
report_user_error(exc_info, err_file)
420
return errors.EXIT_ERROR
273
422
report_bug(exc_info, err_file)
423
return errors.EXIT_INTERNAL_ERROR
426
def print_exception(exc_info, err_file):
427
exc_type, exc_object, exc_tb = exc_info
428
err_file.write("bzr: ERROR: %s.%s: %s\n" % (
429
exc_type.__module__, exc_type.__name__, exc_object))
431
traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
276
434
# TODO: Should these be specially encoding the output?
277
def report_user_error(exc_info, err_file):
278
print >>err_file, "bzr: ERROR:", str(exc_info[1])
435
def report_user_error(exc_info, err_file, advice=None):
436
"""Report to err_file an error that's not an internal error.
438
These don't get a traceback unless -Derror was given.
440
:param exc_info: 3-tuple from sys.exc_info()
441
:param advice: Extra advice to the user to be printed following the
444
if 'error' in debug.debug_flags:
445
print_exception(exc_info, err_file)
447
err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
449
err_file.write("%s\n" % (advice,))
281
452
def report_bug(exc_info, err_file):
282
453
"""Report an exception that probably indicates a bug in bzr"""
284
exc_type, exc_object, exc_tb = exc_info
285
print >>err_file, "bzr: ERROR: %s: %s" % (exc_type, exc_object)
287
traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
289
print >>err_file, 'bzr %s on python %s (%s)' % \
454
print_exception(exc_info, err_file)
456
err_file.write('bzr %s on python %s (%s)\n' % \
290
457
(bzrlib.__version__,
291
'.'.join(map(str, sys.version_info)),
293
print >>err_file, 'arguments: %r' % sys.argv
295
print >>err_file, "** please send this report to bazaar-ng@lists.ubuntu.com"
458
bzrlib._format_version_tuple(sys.version_info),
460
err_file.write('arguments: %r\n' % sys.argv)
462
'encoding: %r, fsenc: %r, lang: %r\n' % (
463
osutils.get_user_encoding(), sys.getfilesystemencoding(),
464
os.environ.get('LANG')))
465
err_file.write("plugins:\n")
466
for name, a_plugin in sorted(plugin.plugins().items()):
467
err_file.write(" %-20s %s [%s]\n" %
468
(name, a_plugin.path(), a_plugin.__version__))
471
*** Bazaar has encountered an internal error.
472
Please report a bug at https://bugs.launchpad.net/bzr/+filebug
473
including this traceback, and a description of what you
474
were doing when the error occurred.
added
removed
bzrlib/trace.py
