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
57
65
from bzrlib.lazy_import import lazy_import
58
66
lazy_import(globals(), """
67
from cStringIO import StringIO
64
from bzrlib.symbol_versioning import (deprecated_function,
68
75
lazy_import(globals(), """
69
from bzrlib import debug
73
_stderr_handler = None
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.
80
# 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
82
106
_bzr_logger = logging.getLogger('bzr')
84
109
def note(*args, **kwargs):
85
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.
87
116
bzrlib.ui.ui_factory.clear_term()
88
117
_bzr_logger.info(*args, **kwargs)
90
120
def warning(*args, **kwargs):
92
122
bzrlib.ui.ui_factory.clear_term()
93
123
_bzr_logger.warning(*args, **kwargs)
126
# configure convenient aliases for output routines
128
# TODO: deprecate them, have one name for each.
96
130
log_error = _bzr_logger.error
97
131
error = _bzr_logger.error
134
_last_mutter_flush_time = None
100
136
def mutter(fmt, *args):
137
global _last_mutter_flush_time
101
138
if _trace_file is None:
103
140
if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
131
196
if size <= 4 << 20:
133
198
old_fname = trace_fname + '.old'
134
from osutils import rename
135
rename(trace_fname, old_fname)
199
osutils.rename(trace_fname, old_fname)
140
def open_tracefile(tracefilename=None):
141
# Messages are always written to here, so that we have some
142
# information if something goes wrong. In a future version this
143
# file will be removed on successful completion.
144
global _file_handler, _bzr_log_file
147
if tracefilename is None:
204
def _get_bzr_log_filename():
205
bzr_log = os.environ.get('BZR_LOG')
208
home = os.environ.get('BZR_HOME')
148
210
if sys.platform == 'win32':
149
211
from bzrlib import win32utils
150
212
home = win32utils.get_home_location()
152
214
home = os.path.expanduser('~')
153
tracefilename = os.path.join(home, '.bzr.log')
155
trace_fname = os.path.expanduser(tracefilename)
156
_rollover_trace_maybe(trace_fname)
215
return os.path.join(home, '.bzr.log')
219
"""Open the .bzr.log trace file.
221
If the log is more than a particular length, the old file is renamed to
222
.bzr.log.old and a new file is started. Otherwise, we append to the
225
This sets the global _bzr_log_filename.
227
global _bzr_log_filename
228
_bzr_log_filename = _get_bzr_log_filename()
229
_rollover_trace_maybe(_bzr_log_filename)
159
#tf = codecs.open(trace_fname, 'at', 'utf8', buffering=LINE_BUFFERED)
160
tf = open(trace_fname, 'at', LINE_BUFFERED)
162
# tf.tell() on windows always return 0 until some writing done
165
tf.write("this is a debug log for diagnosing/reporting problems in bzr\n")
166
tf.write("you can delete or truncate this file, or include sections in\n")
167
tf.write("bug reports to bazaar@lists.canonical.com\n\n")
168
_file_handler = logging.StreamHandler(tf)
169
fmt = r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s'
170
datefmt = r'%a %H:%M:%S'
171
_file_handler.setFormatter(logging.Formatter(fmt, datefmt))
172
_file_handler.setLevel(logging.DEBUG)
173
logging.getLogger('').addHandler(_file_handler)
231
bzr_log_file = open(_bzr_log_filename, 'at', 1) # line buffered
232
# bzr_log_file.tell() on windows always return 0 until some writing done
233
bzr_log_file.write('\n')
234
if bzr_log_file.tell() <= 2:
235
bzr_log_file.write("this is a debug log for diagnosing/reporting problems in bzr\n")
236
bzr_log_file.write("you can delete or truncate this file, or include sections in\n")
237
bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
174
239
except IOError, e:
175
240
warning("failed to open trace file: %s" % (e))
178
@deprecated_function(zero_nine)
179
def log_exception(msg=None):
180
"""Log the last exception to stderr and the trace file.
182
The exception string representation is used as the error
183
summary, unless msg is given.
187
log_exception_quietly()
241
# TODO: What should happen if we fail to open the trace file? Maybe the
242
# objects should be pointed at /dev/null or the equivalent? Currently
243
# returns None which will cause failures later.
247
def enable_default_logging():
248
"""Configure default logging: messages to stderr and debug to .bzr.log
250
This should only be called once per process.
252
Non-command-line programs embedding bzrlib do not need to call this. They
253
can instead either pass a file to _push_log_file, or act directly on
254
logging.getLogger("bzr").
256
Output can be redirected away by calling _push_log_file.
258
# Do this before we open the log file, so we prevent
259
# get_terminal_encoding() from mutter()ing multiple times
260
term_encoding = osutils.get_terminal_encoding()
261
start_time = osutils.format_local_date(_bzr_log_start_time,
263
# create encoded wrapper around stderr
264
bzr_log_file = _open_bzr_log()
265
if bzr_log_file is not None:
266
bzr_log_file.write(start_time.encode('utf-8') + '\n')
267
push_log_file(bzr_log_file,
268
r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
269
r'%Y-%m-%d %H:%M:%S')
270
# after hooking output into bzr_log, we also need to attach a stderr
271
# handler, writing only at level info and with encoding
272
writer_factory = codecs.getwriter(term_encoding)
273
encoded_stderr = writer_factory(sys.stderr, errors='replace')
274
stderr_handler = logging.StreamHandler(encoded_stderr)
275
stderr_handler.setLevel(logging.INFO)
276
logging.getLogger('bzr').addHandler(stderr_handler)
279
def push_log_file(to_file, log_format=None, date_format=None):
280
"""Intercept log and trace messages and send them to a file.
282
:param to_file: A file-like object to which messages will be sent.
284
:returns: A memento that should be passed to _pop_log_file to restore the
285
previously active logging.
289
new_handler = logging.StreamHandler(to_file)
290
new_handler.setLevel(logging.DEBUG)
291
if log_format is None:
292
log_format = '%(levelname)8s %(message)s'
293
new_handler.setFormatter(logging.Formatter(log_format, date_format))
294
# save and remove any existing log handlers
295
bzr_logger = logging.getLogger('bzr')
296
old_handlers = bzr_logger.handlers[:]
297
del bzr_logger.handlers[:]
298
# set that as the default logger
299
bzr_logger.addHandler(new_handler)
300
bzr_logger.setLevel(logging.DEBUG)
301
# TODO: check if any changes are needed to the root logger
303
# TODO: also probably need to save and restore the level on bzr_logger.
304
# but maybe we can avoid setting the logger level altogether, and just set
305
# the level on the handler?
307
# save the old trace file
308
old_trace_file = _trace_file
309
# send traces to the new one
310
_trace_file = to_file
311
result = new_handler, _trace_file
312
return ('log_memento', old_handlers, new_handler, old_trace_file, to_file)
315
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
316
"""Undo changes to logging/tracing done by _push_log_file.
318
This flushes, but does not close the trace file.
320
Takes the memento returned from _push_log_file."""
322
_trace_file = old_trace_file
323
bzr_logger = logging.getLogger('bzr')
324
bzr_logger.removeHandler(new_handler)
325
# must be closed, otherwise logging will try to close it atexit, and the
326
# file will likely already be closed underneath.
328
bzr_logger.handlers = old_handlers
329
new_trace_file.flush()
332
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
333
def enable_test_log(to_file):
334
"""Redirect logging to a temporary file for a test
336
:returns: an opaque reference that should be passed to disable_test_log
337
after the test completes.
339
return push_log_file(to_file)
342
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
343
def disable_test_log(memento):
344
return pop_log_file(memento)
190
347
def log_exception_quietly():
194
351
interesting to developers but not to users. For example,
195
352
errors loading plugins.
198
354
mutter(traceback.format_exc())
201
def enable_default_logging():
202
"""Configure default logging to stderr and .bzr.log"""
203
# FIXME: if this is run twice, things get confused
204
global _stderr_handler, _file_handler, _trace_file, _bzr_log_file
205
_stderr_handler = logging.StreamHandler()
206
logging.getLogger('').addHandler(_stderr_handler)
207
_stderr_handler.setLevel(logging.INFO)
208
if not _file_handler:
210
_trace_file = _bzr_log_file
212
_file_handler.setLevel(logging.DEBUG)
213
_bzr_logger.setLevel(logging.DEBUG)
357
def set_verbosity_level(level):
358
"""Set the verbosity level.
360
:param level: -ve for quiet, 0 for normal, +ve for verbose
362
global _verbosity_level
363
_verbosity_level = level
364
_update_logging_level(level < 0)
367
def get_verbosity_level():
368
"""Get the verbosity level.
370
See set_verbosity_level() for values.
372
return _verbosity_level
216
375
def be_quiet(quiet=True):
217
global _stderr_handler, _stderr_quiet
219
_stderr_quiet = quiet
221
_stderr_handler.setLevel(logging.WARNING)
223
_stderr_handler.setLevel(logging.INFO)
376
# Perhaps this could be deprecated now ...
378
set_verbosity_level(-1)
380
set_verbosity_level(0)
383
def _update_logging_level(quiet=True):
384
"""Hide INFO messages if quiet."""
386
_bzr_logger.setLevel(logging.WARNING)
388
_bzr_logger.setLevel(logging.INFO)
392
"""Is the verbosity level negative?"""
393
return _verbosity_level < 0
397
"""Is the verbosity level positive?"""
398
return _verbosity_level > 0
401
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
231
402
def disable_default_logging():
232
403
"""Turn off default log handlers.
234
This is intended to be used by the test framework, which doesn't
235
want leakage from the code-under-test into the main logs.
238
l = logging.getLogger('')
239
l.removeHandler(_stderr_handler)
241
l.removeHandler(_file_handler)
245
def enable_test_log(to_file):
246
"""Redirect logging to a temporary file for a test
248
returns an opaque reference that should be passed to disable_test_log
249
after the test completes.
251
disable_default_logging()
254
hdlr = logging.StreamHandler(to_file)
255
hdlr.setLevel(logging.DEBUG)
256
hdlr.setFormatter(logging.Formatter('%(levelname)8s %(message)s'))
257
_bzr_logger.addHandler(hdlr)
258
_bzr_logger.setLevel(logging.DEBUG)
259
result = hdlr, _trace_file, _trace_depth
260
_trace_file = to_file
265
def disable_test_log((test_log_hdlr, old_trace_file, old_trace_depth)):
266
_bzr_logger.removeHandler(test_log_hdlr)
267
test_log_hdlr.close()
270
_trace_file = old_trace_file
271
_trace_depth = old_trace_depth
273
enable_default_logging()
405
Don't call this method, use _push_log_file and _pop_log_file instead.
410
_short_fields = ('VmPeak', 'VmSize', 'VmRSS')
412
def debug_memory(message='', short=True):
413
"""Write out a memory dump."""
415
status_file = file('/proc/%s/status' % os.getpid(), 'rb')
419
status = status_file.read()
424
for line in status.splitlines():
428
for field in _short_fields:
429
if line.startswith(field):
276
434
def report_exception(exc_info, err_file):
435
"""Report an exception to err_file (typically stderr) and to .bzr.log.
437
This will show either a full traceback or a short message as appropriate.
439
:return: The appropriate exit code for this error.
277
441
exc_type, exc_object, exc_tb = exc_info
278
442
# Log the full traceback to ~/.bzr.log
279
443
log_exception_quietly()
280
444
if (isinstance(exc_object, IOError)
281
445
and getattr(exc_object, 'errno', None) == errno.EPIPE):
282
print >>err_file, "bzr: broken pipe"
446
err_file.write("bzr: broken pipe\n")
447
return errors.EXIT_ERROR
283
448
elif isinstance(exc_object, KeyboardInterrupt):
284
print >>err_file, "bzr: interrupted"
449
err_file.write("bzr: interrupted\n")
450
return errors.EXIT_ERROR
451
elif isinstance(exc_object, ImportError) \
452
and str(exc_object).startswith("No module named "):
453
report_user_error(exc_info, err_file,
454
'You may need to install this Python library separately.')
455
return errors.EXIT_ERROR
285
456
elif not getattr(exc_object, 'internal_error', True):
286
457
report_user_error(exc_info, err_file)
458
return errors.EXIT_ERROR
287
459
elif isinstance(exc_object, (OSError, IOError)):
288
460
# Might be nice to catch all of these and show them as something more
289
461
# specific, but there are too many cases at the moment.
290
462
report_user_error(exc_info, err_file)
463
return errors.EXIT_ERROR
292
465
report_bug(exc_info, err_file)
466
return errors.EXIT_INTERNAL_ERROR
469
def print_exception(exc_info, err_file):
470
exc_type, exc_object, exc_tb = exc_info
471
err_file.write("bzr: ERROR: %s.%s: %s\n" % (
472
exc_type.__module__, exc_type.__name__, exc_object))
474
traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
295
477
# TODO: Should these be specially encoding the output?
296
def report_user_error(exc_info, err_file):
478
def report_user_error(exc_info, err_file, advice=None):
297
479
"""Report to err_file an error that's not an internal error.
299
481
These don't get a traceback unless -Derror was given.
483
:param exc_info: 3-tuple from sys.exc_info()
484
:param advice: Extra advice to the user to be printed following the
301
487
if 'error' in debug.debug_flags:
302
report_bug(exc_info, err_file)
488
print_exception(exc_info, err_file)
304
print >>err_file, "bzr: ERROR:", str(exc_info[1])
490
err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
492
err_file.write("%s\n" % (advice,))
307
495
def report_bug(exc_info, err_file):
308
496
"""Report an exception that probably indicates a bug in bzr"""
310
exc_type, exc_object, exc_tb = exc_info
311
print >>err_file, "bzr: ERROR: %s.%s: %s" % (
312
exc_type.__module__, exc_type.__name__, exc_object)
314
traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
316
print >>err_file, 'bzr %s on python %s (%s)' % \
497
print_exception(exc_info, err_file)
499
err_file.write('bzr %s on python %s (%s)\n' % \
317
500
(bzrlib.__version__,
318
'.'.join(map(str, sys.version_info)),
320
print >>err_file, 'arguments: %r' % sys.argv
322
print >>err_file, "** please send this report to bazaar@lists.ubuntu.com"
501
bzrlib._format_version_tuple(sys.version_info),
503
err_file.write('arguments: %r\n' % sys.argv)
505
'encoding: %r, fsenc: %r, lang: %r\n' % (
506
osutils.get_user_encoding(), sys.getfilesystemencoding(),
507
os.environ.get('LANG')))
508
err_file.write("plugins:\n")
509
for name, a_plugin in sorted(plugin.plugins().items()):
510
err_file.write(" %-20s %s [%s]\n" %
511
(name, a_plugin.path(), a_plugin.__version__))
514
*** Bazaar has encountered an internal error.
515
Please report a bug at https://bugs.launchpad.net/bzr/+filebug
516
including this traceback, and a description of what you
517
were doing when the error occurred.