13
13
# You should have received a copy of the GNU General Public License
14
14
# along with this program; if not, write to the Free Software
15
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
15
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
17
"""Messages and logging for bazaar-ng.
17
"""Messages and logging.
19
19
Messages are supplied by callers as a string-formatting template, plus values
20
20
to be inserted into it. The actual %-formatting is deferred to the log
109
108
def note(*args, **kwargs):
110
# FIXME note always emits utf-8, regardless of the terminal encoding
109
"""Output a note to the user.
111
Takes the same parameters as logging.info.
112
115
# FIXME: clearing the ui and then going through the abstract logging
113
116
# framework is whack; we should probably have a logging Handler that
114
117
# deals with terminal output if needed.
116
bzrlib.ui.ui_factory.clear_term()
118
ui.ui_factory.clear_term()
117
119
_bzr_logger.info(*args, **kwargs)
120
122
def warning(*args, **kwargs):
122
bzrlib.ui.ui_factory.clear_term()
123
ui.ui_factory.clear_term()
123
124
_bzr_logger.warning(*args, **kwargs)
126
# configure convenient aliases for output routines
128
# TODO: deprecate them, have one name for each.
130
log_error = _bzr_logger.error
131
error = _bzr_logger.error
127
def show_error(*args, **kwargs):
128
"""Show an error message to the user.
130
Don't use this for exceptions, use report_exception instead.
132
_bzr_logger.error(*args, **kwargs)
134
135
def mutter(fmt, *args):
135
136
if _trace_file is None:
138
# XXX: Don't check this every time; instead anyone who closes the file
139
# ought to deregister it. We can tolerate None.
137
140
if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
214
217
This sets the global _bzr_log_filename.
216
219
global _bzr_log_filename
221
def _open_or_create_log_file(filename):
222
"""Open existing log file, or create with ownership and permissions
224
It inherits the ownership and permissions (masked by umask) from
225
the containing directory to cope better with being run under sudo
226
with $HOME still set to the user's homedir.
228
flags = os.O_WRONLY | os.O_APPEND | osutils.O_TEXT
231
fd = os.open(filename, flags)
234
if e.errno != errno.ENOENT:
237
fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0666)
239
if e.errno != errno.EEXIST:
242
osutils.copy_ownership_from_path(filename)
244
return os.fdopen(fd, 'at', 0) # unbuffered
217
247
_bzr_log_filename = _get_bzr_log_filename()
218
248
_rollover_trace_maybe(_bzr_log_filename)
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
250
bzr_log_file = _open_or_create_log_file(_bzr_log_filename)
222
251
bzr_log_file.write('\n')
223
252
if bzr_log_file.tell() <= 2:
224
253
bzr_log_file.write("this is a debug log for diagnosing/reporting problems in bzr\n")
225
254
bzr_log_file.write("you can delete or truncate this file, or include sections in\n")
226
255
bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
227
257
return bzr_log_file
229
warning("failed to open trace file: %s" % (e))
259
except EnvironmentError, e:
260
# If we are failing to open the log, then most likely logging has not
261
# been set up yet. So we just write to stderr rather than using
262
# 'warning()'. If we using warning(), users get the unhelpful 'no
263
# handlers registered for "bzr"' when something goes wrong on the
264
# server. (bug #503886)
265
sys.stderr.write("failed to open trace file: %s\n" % (e,))
230
266
# TODO: What should happen if we fail to open the trace file? Maybe the
231
267
# objects should be pointed at /dev/null or the equivalent? Currently
232
268
# returns None which will cause failures later.
235
272
def enable_default_logging():
236
273
"""Configure default logging: messages to stderr and debug to .bzr.log
238
275
This should only be called once per process.
240
277
Non-command-line programs embedding bzrlib do not need to call this. They
241
278
can instead either pass a file to _push_log_file, or act directly on
242
279
logging.getLogger("bzr").
244
281
Output can be redirected away by calling _push_log_file.
283
:return: A memento from push_log_file for restoring the log state.
246
# create encoded wrapper around stderr
285
start_time = osutils.format_local_date(_bzr_log_start_time,
247
287
bzr_log_file = _open_bzr_log()
248
push_log_file(bzr_log_file,
288
if bzr_log_file is not None:
289
bzr_log_file.write(start_time.encode('utf-8') + '\n')
290
memento = push_log_file(bzr_log_file,
249
291
r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
250
292
r'%Y-%m-%d %H:%M:%S')
251
293
# after hooking output into bzr_log, we also need to attach a stderr
252
294
# 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)
295
stderr_handler = EncodedStreamHandler(sys.stderr,
296
osutils.get_terminal_encoding(), 'replace', level=logging.INFO)
257
297
logging.getLogger('bzr').addHandler(stderr_handler)
260
301
def push_log_file(to_file, log_format=None, date_format=None):
296
336
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
297
337
"""Undo changes to logging/tracing done by _push_log_file.
299
This flushes, but does not close the trace file.
339
This flushes, but does not close the trace file (so that anything that was
301
342
Takes the memento returned from _push_log_file."""
302
343
global _trace_file
303
344
_trace_file = old_trace_file
304
345
bzr_logger = logging.getLogger('bzr')
305
346
bzr_logger.removeHandler(new_handler)
306
# must be closed, otherwise logging will try to close it atexit, and the
347
# must be closed, otherwise logging will try to close it at exit, and the
307
348
# file will likely already be closed underneath.
308
349
new_handler.close()
309
350
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)
351
if new_trace_file is not None:
352
new_trace_file.flush()
328
355
def log_exception_quietly():
329
356
"""Log the last exception to the trace file only.
331
Used for exceptions that occur internally and that may be
332
interesting to developers but not to users. For example,
358
Used for exceptions that occur internally and that may be
359
interesting to developers but not to users. For example,
333
360
errors loading plugins.
335
362
mutter(traceback.format_exc())
379
406
return _verbosity_level > 0
382
@symbol_versioning.deprecated_function(symbol_versioning.one_two)
383
def disable_default_logging():
384
"""Turn off default log handlers.
386
Don't call this method, use _push_log_file and _pop_log_file instead.
391
_short_fields = ('VmPeak', 'VmSize', 'VmRSS')
393
409
def debug_memory(message='', short=True):
394
410
"""Write out a memory dump."""
411
if sys.platform == 'win32':
412
from bzrlib import win32utils
413
win32utils.debug_memory_win32api(message=message, short=short)
415
_debug_memory_proc(message=message, short=short)
418
_short_fields = ('VmPeak', 'VmSize', 'VmRSS')
420
def _debug_memory_proc(message='', short=True):
396
422
status_file = file('/proc/%s/status' % os.getpid(), 'rb')
440
def _dump_memory_usage(err_file):
443
fd, name = tempfile.mkstemp(prefix="bzr_memdump", suffix=".json")
444
dump_file = os.fdopen(fd, 'w')
445
from meliae import scanner
446
scanner.dump_gc_objects(dump_file)
447
err_file.write("Memory dumped to %s\n" % name)
449
err_file.write("Dumping memory requires meliae module.\n")
450
log_exception_quietly()
452
err_file.write("Exception while dumping memory.\n")
453
log_exception_quietly()
455
if dump_file is not None:
461
def _qualified_exception_name(eclass, unqualified_bzrlib_errors=False):
462
"""Give name of error class including module for non-builtin exceptions
464
If `unqualified_bzrlib_errors` is True, errors specific to bzrlib will
465
also omit the module prefix.
467
class_name = eclass.__name__
468
module_name = eclass.__module__
469
if module_name in ("exceptions", "__main__") or (
470
unqualified_bzrlib_errors and module_name == "bzrlib.errors"):
472
return "%s.%s" % (module_name, class_name)
415
475
def report_exception(exc_info, err_file):
416
476
"""Report an exception to err_file (typically stderr) and to .bzr.log.
420
480
:return: The appropriate exit code for this error.
422
exc_type, exc_object, exc_tb = exc_info
423
482
# Log the full traceback to ~/.bzr.log
424
483
log_exception_quietly()
425
if (isinstance(exc_object, IOError)
426
and getattr(exc_object, 'errno', None) == errno.EPIPE):
427
err_file.write("bzr: broken pipe\n")
484
if 'error' in debug.debug_flags:
485
print_exception(exc_info, err_file)
428
486
return errors.EXIT_ERROR
429
elif isinstance(exc_object, KeyboardInterrupt):
487
exc_type, exc_object, exc_tb = exc_info
488
if isinstance(exc_object, KeyboardInterrupt):
430
489
err_file.write("bzr: interrupted\n")
431
490
return errors.EXIT_ERROR
491
elif isinstance(exc_object, MemoryError):
492
err_file.write("bzr: out of memory\n")
493
if 'mem_dump' in debug.debug_flags:
494
_dump_memory_usage(err_file)
496
err_file.write("Use -Dmem_dump to dump memory to a file.\n")
497
return errors.EXIT_ERROR
432
498
elif isinstance(exc_object, ImportError) \
433
499
and str(exc_object).startswith("No module named "):
434
500
report_user_error(exc_info, err_file,
437
503
elif not getattr(exc_object, 'internal_error', True):
438
504
report_user_error(exc_info, err_file)
439
505
return errors.EXIT_ERROR
440
elif isinstance(exc_object, (OSError, IOError)):
506
elif osutils.is_environment_error(exc_object):
507
if getattr(exc_object, 'errno', None) == errno.EPIPE:
508
err_file.write("bzr: broken pipe\n")
509
return errors.EXIT_ERROR
441
510
# Might be nice to catch all of these and show them as something more
442
511
# specific, but there are too many cases at the moment.
443
512
report_user_error(exc_info, err_file)
476
542
def report_bug(exc_info, err_file):
477
543
"""Report an exception that probably indicates a bug in bzr"""
478
print_exception(exc_info, err_file)
480
err_file.write('bzr %s on python %s (%s)\n' % \
482
bzrlib._format_version_tuple(sys.version_info),
484
err_file.write('arguments: %r\n' % sys.argv)
486
'encoding: %r, fsenc: %r, lang: %r\n' % (
487
osutils.get_user_encoding(), sys.getfilesystemencoding(),
488
os.environ.get('LANG')))
489
err_file.write("plugins:\n")
490
for name, a_plugin in sorted(plugin.plugins().items()):
491
err_file.write(" %-20s %s [%s]\n" %
492
(name, a_plugin.path(), a_plugin.__version__))
495
*** Bazaar has encountered an internal error.
496
Please report a bug at https://bugs.launchpad.net/bzr/+filebug
497
including this traceback, and a description of what you
498
were doing when the error occurred.
544
from bzrlib.crash import report_bug
545
report_bug(exc_info, err_file)
548
def _flush_stdout_stderr():
549
# called from the bzrlib library finalizer returned by bzrlib.initialize()
553
except ValueError, e:
554
# On Windows, I get ValueError calling stdout.flush() on a closed
559
if e.errno in [errno.EINVAL, errno.EPIPE]:
566
# called from the bzrlib library finalizer returned by bzrlib.initialize()
572
class EncodedStreamHandler(logging.Handler):
573
"""Robustly write logging events to a stream using the specified encoding
575
Messages are expected to be formatted to unicode, but UTF-8 byte strings
576
are also accepted. An error during formatting or a str message in another
577
encoding will be quitely noted as an error in the Bazaar log file.
579
The stream is not closed so sys.stdout or sys.stderr may be passed.
582
def __init__(self, stream, encoding=None, errors='strict', level=0):
583
logging.Handler.__init__(self, level)
586
encoding = getattr(stream, "encoding", "ascii")
587
self.encoding = encoding
591
flush = getattr(self.stream, "flush", None)
592
if flush is not None:
595
def emit(self, record):
597
line = self.format(record)
598
if not isinstance(line, unicode):
599
line = line.decode("utf-8")
600
self.stream.write(line.encode(self.encoding, self.errors) + "\n")
602
log_exception_quietly()
603
# Try saving the details that would have been logged in some form
604
msg = args = "<Unformattable>"
606
msg = repr(record.msg).encode("ascii")
607
args = repr(record.args).encode("ascii")
610
# Using mutter() bypasses the logging module and writes directly
611
# to the file so there's no danger of getting into a loop here.
612
mutter("Logging record unformattable: %s %% %s", msg, args)
615
class Config(object):
616
"""Configuration of message tracing in bzrlib.
618
This implements the context manager protocol and should manage any global
619
variables still used. The default config used is DefaultConfig, but
620
embedded uses of bzrlib may wish to use a custom manager.
624
return self # This is bound to the 'as' clause in a with statement.
626
def __exit__(self, exc_type, exc_val, exc_tb):
627
return False # propogate exceptions.
630
class DefaultConfig(Config):
631
"""A default configuration for tracing of messages in bzrlib.
633
This implements the context manager protocol.
637
self._original_filename = _bzr_log_filename
638
self._original_state = enable_default_logging()
639
return self # This is bound to the 'as' clause in a with statement.
641
def __exit__(self, exc_type, exc_val, exc_tb):
642
pop_log_file(self._original_state)
643
global _bzr_log_filename
644
_bzr_log_filename = self._original_filename
645
return False # propogate exceptions.
added
removed
bzrlib/trace.py
