23
23
Messages are classified by severity levels: critical, error, warning, info,
26
They can be sent to two places: stderr, and `$XDG_CACHE_HOME/breezy/brz.log`.
27
For purposes such as running the test suite, they can also be redirected away
28
from both of those two places to another location.
26
They can be sent to two places: to stderr, and to ~/.bzr.log. For purposes
27
such as running the test suite, they can also be redirected away from both of
28
those two places to another location.
30
`brz.log` gets all messages, and full tracebacks for uncaught exceptions.
30
~/.bzr.log gets all messages, and full tracebacks for uncaught exceptions.
31
31
This trace file is always in UTF-8, regardless of the user's default encoding,
32
32
so that we can always rely on writing any message.
54
56
# increased cost of logging.py is not so bad, and we could standardize on
58
from io import StringIO
64
from .lazy_import import lazy_import
64
from brzlib.lazy_import import lazy_import
65
65
lazy_import(globals(), """
66
from cStringIO import StringIO
72
75
lazy_import(globals(), """
85
# global verbosity for breezy; controls the log level for stderr; 0=normal; <0
85
# global verbosity for brzlib; controls the log level for stderr; 0=normal; <0
86
86
# is quiet; >0 is verbose.
87
87
_verbosity_level = 0
92
92
# than push/pop_log_file.
95
# Absolute path for brz.log. Not changed even if the log/trace output is
95
# Absolute path for ~/.bzr.log. Not changed even if the log/trace output is
96
96
# redirected elsewhere. Used to show the location in --version.
97
_brz_log_filename = None
97
_bzr_log_filename = None
99
99
# The time the first message was written to the trace file, so that we can
100
100
# show relative times since startup.
101
_brz_log_start_time = breezy._start_time
101
_bzr_log_start_time = brzlib._start_time
104
104
# held in a global for quick reference
105
_brz_logger = logging.getLogger('brz')
105
_bzr_logger = logging.getLogger('bzr')
108
108
def note(*args, **kwargs):
116
116
# framework is whack; we should probably have a logging Handler that
117
117
# deals with terminal output if needed.
118
118
ui.ui_factory.clear_term()
119
_brz_logger.info(*args, **kwargs)
119
_bzr_logger.info(*args, **kwargs)
122
122
def warning(*args, **kwargs):
123
123
ui.ui_factory.clear_term()
124
_brz_logger.warning(*args, **kwargs)
124
_bzr_logger.warning(*args, **kwargs)
127
127
def show_error(*args, **kwargs):
130
130
Don't use this for exceptions, use report_exception instead.
132
_brz_logger.error(*args, **kwargs)
136
"""Compat class for displaying bytes on Python 2."""
139
return 'b' + str.__repr__(self)
141
def __unicode__(self):
142
return self.decode('ascii', 'replace')
132
_bzr_logger.error(*args, **kwargs)
145
135
def mutter(fmt, *args):
150
140
if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
153
# Let format strings be specified as ascii bytes to help Python 2
154
if isinstance(fmt, bytes):
155
fmt = fmt.decode('ascii', 'replace')
143
if isinstance(fmt, unicode):
144
fmt = fmt.encode('utf8')
147
# It seems that if we do ascii % (unicode, ascii) we can
148
# get a unicode cannot encode ascii error, so make sure that "fmt"
149
# is a unicode string
152
if isinstance(arg, unicode):
153
arg = arg.encode('utf8')
154
real_args.append(arg)
155
out = fmt % tuple(real_args)
161
158
now = time.time()
162
out = '%0.3f %s\n' % (now - _brz_log_start_time, out)
163
_trace_file.write(out.encode('utf-8'))
159
timestamp = '%0.3f ' % (now - _bzr_log_start_time,)
160
out = timestamp + out + '\n'
161
_trace_file.write(out)
164
162
# there's no explicit flushing; the file is typically line buffered.
198
def _get_brz_log_filename():
199
"""Return the brz log filename.
201
:return: A path to the log file
202
:raise EnvironmentError: If the cache directory could not be created
204
brz_log = osutils.path_from_environ('BRZ_LOG')
207
return os.path.join(bedding.cache_dir(), 'brz.log')
211
"""Open the brz.log trace file.
196
def _get_bzr_log_filename():
197
bzr_log = osutils.path_from_environ('BZR_LOG')
200
home = osutils.path_from_environ('BZR_HOME')
202
# GZ 2012-02-01: Logging to the home dir is bad, but XDG is unclear
203
# over what would be better. On windows, bug 240550
204
# suggests LOCALAPPDATA be used instead.
205
home = osutils._get_home_dir()
206
return os.path.join(home, '.bzr.log')
210
"""Open the .bzr.log trace file.
213
212
If the log is more than a particular length, the old file is renamed to
214
brz.log.old and a new file is started. Otherwise, we append to the
213
.bzr.log.old and a new file is started. Otherwise, we append to the
217
This sets the global _brz_log_filename.
216
This sets the global _bzr_log_filename.
219
global _brz_log_filename
218
global _bzr_log_filename
221
220
def _open_or_create_log_file(filename):
222
221
"""Open existing log file, or create with ownership and permissions
231
230
fd = os.open(filename, flags)
234
233
if e.errno != errno.ENOENT:
237
fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0o666)
236
fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0666)
239
238
if e.errno != errno.EEXIST:
242
241
osutils.copy_ownership_from_path(filename)
244
return os.fdopen(fd, 'ab', 0) # unbuffered
243
return os.fdopen(fd, 'at', 0) # unbuffered
246
_bzr_log_filename = _get_bzr_log_filename()
247
_rollover_trace_maybe(_bzr_log_filename)
247
_brz_log_filename = _get_brz_log_filename()
248
_rollover_trace_maybe(_brz_log_filename)
250
brz_log_file = _open_or_create_log_file(_brz_log_filename)
251
brz_log_file.write(b'\n')
252
if brz_log_file.tell() <= 2:
254
b"this is a debug log for diagnosing/reporting problems in brz\n")
256
b"you can delete or truncate this file, or include sections in\n")
258
b"bug reports to https://bugs.launchpad.net/brz/+filebug\n\n")
262
except EnvironmentError as e:
249
bzr_log_file = _open_or_create_log_file(_bzr_log_filename)
250
bzr_log_file.write('\n')
251
if bzr_log_file.tell() <= 2:
252
bzr_log_file.write("this is a debug log for diagnosing/reporting problems in bzr\n")
253
bzr_log_file.write("you can delete or truncate this file, or include sections in\n")
254
bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
258
except EnvironmentError, e:
263
259
# If we are failing to open the log, then most likely logging has not
264
260
# been set up yet. So we just write to stderr rather than using
265
261
# 'warning()'. If we using warning(), users get the unhelpful 'no
266
# handlers registered for "brz"' when something goes wrong on the
262
# handlers registered for "bzr"' when something goes wrong on the
267
263
# server. (bug #503886)
268
264
sys.stderr.write("failed to open trace file: %s\n" % (e,))
269
265
# TODO: What should happen if we fail to open the trace file? Maybe the
275
271
def enable_default_logging():
276
"""Configure default logging: messages to stderr and debug to brz.log
272
"""Configure default logging: messages to stderr and debug to .bzr.log
278
274
This should only be called once per process.
280
Non-command-line programs embedding breezy do not need to call this. They
276
Non-command-line programs embedding brzlib do not need to call this. They
281
277
can instead either pass a file to _push_log_file, or act directly on
282
logging.getLogger("brz").
278
logging.getLogger("bzr").
284
280
Output can be redirected away by calling _push_log_file.
286
282
:return: A memento from push_log_file for restoring the log state.
288
start_time = osutils.format_local_date(_brz_log_start_time,
284
start_time = osutils.format_local_date(_bzr_log_start_time,
289
285
timezone='local')
290
brz_log_file = _open_brz_log()
291
if brz_log_file is not None:
292
brz_log_file.write(start_time.encode('utf-8') + b'\n')
293
memento = push_log_file(
286
bzr_log_file = _open_bzr_log()
287
if bzr_log_file is not None:
288
bzr_log_file.write(start_time.encode('utf-8') + '\n')
289
memento = push_log_file(bzr_log_file,
295
290
r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
296
291
r'%Y-%m-%d %H:%M:%S')
297
# after hooking output into brz_log, we also need to attach a stderr
292
# after hooking output into bzr_log, we also need to attach a stderr
298
293
# handler, writing only at level info and with encoding
299
stderr_handler = logging.StreamHandler(stream=sys.stderr)
300
logging.getLogger('brz').addHandler(stderr_handler)
294
stderr_handler = EncodedStreamHandler(sys.stderr,
295
osutils.get_terminal_encoding(), 'replace', level=logging.INFO)
296
logging.getLogger('bzr').addHandler(stderr_handler)
316
312
log_format = '%(levelname)8s %(message)s'
317
313
new_handler.setFormatter(logging.Formatter(log_format, date_format))
318
314
# save and remove any existing log handlers
319
brz_logger = logging.getLogger('brz')
320
old_handlers = brz_logger.handlers[:]
321
del brz_logger.handlers[:]
315
bzr_logger = logging.getLogger('bzr')
316
old_handlers = bzr_logger.handlers[:]
317
del bzr_logger.handlers[:]
322
318
# set that as the default logger
323
brz_logger.addHandler(new_handler)
324
brz_logger.setLevel(logging.DEBUG)
319
bzr_logger.addHandler(new_handler)
320
bzr_logger.setLevel(logging.DEBUG)
325
321
# TODO: check if any changes are needed to the root logger
327
# TODO: also probably need to save and restore the level on brz_logger.
323
# TODO: also probably need to save and restore the level on bzr_logger.
328
324
# but maybe we can avoid setting the logger level altogether, and just set
329
325
# the level on the handler?
332
328
old_trace_file = _trace_file
333
329
# send traces to the new one
334
330
_trace_file = to_file
331
result = new_handler, _trace_file
335
332
return ('log_memento', old_handlers, new_handler, old_trace_file, to_file)
338
def pop_log_file(entry):
335
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
339
336
"""Undo changes to logging/tracing done by _push_log_file.
341
338
This flushes, but does not close the trace file (so that anything that was
344
341
Takes the memento returned from _push_log_file."""
345
(magic, old_handlers, new_handler, old_trace_file, new_trace_file) = entry
346
342
global _trace_file
347
343
_trace_file = old_trace_file
348
brz_logger = logging.getLogger('brz')
349
brz_logger.removeHandler(new_handler)
344
bzr_logger = logging.getLogger('bzr')
345
bzr_logger.removeHandler(new_handler)
350
346
# must be closed, otherwise logging will try to close it at exit, and the
351
347
# file will likely already be closed underneath.
352
348
new_handler.close()
353
brz_logger.handlers = old_handlers
349
bzr_logger.handlers = old_handlers
354
350
if new_trace_file is not None:
355
351
new_trace_file.flush()
412
408
def debug_memory(message='', short=True):
413
409
"""Write out a memory dump."""
414
410
if sys.platform == 'win32':
415
from breezy import win32utils
411
from brzlib import win32utils
416
412
win32utils.debug_memory_win32api(message=message, short=short)
418
414
_debug_memory_proc(message=message, short=short)
421
417
_short_fields = ('VmPeak', 'VmSize', 'VmRSS')
424
419
def _debug_memory_proc(message='', short=True):
426
status_file = open('/proc/%s/status' % os.getpid(), 'rb')
421
status_file = file('/proc/%s/status' % os.getpid(), 'rb')
445
439
def _dump_memory_usage(err_file):
448
fd, name = tempfile.mkstemp(prefix="brz_memdump", suffix=".json")
442
fd, name = tempfile.mkstemp(prefix="bzr_memdump", suffix=".json")
449
443
dump_file = os.fdopen(fd, 'w')
450
444
from meliae import scanner
451
445
scanner.dump_gc_objects(dump_file)
466
def _qualified_exception_name(eclass, unqualified_breezy_errors=False):
460
def _qualified_exception_name(eclass, unqualified_brzlib_errors=False):
467
461
"""Give name of error class including module for non-builtin exceptions
469
If `unqualified_breezy_errors` is True, errors specific to breezy will
463
If `unqualified_brzlib_errors` is True, errors specific to brzlib will
470
464
also omit the module prefix.
472
466
class_name = eclass.__name__
473
467
module_name = eclass.__module__
474
if module_name in ("builtins", "exceptions", "__main__") or (
475
unqualified_breezy_errors and module_name == "breezy.errors"):
468
if module_name in ("exceptions", "__main__") or (
469
unqualified_brzlib_errors and module_name == "brzlib.errors"):
476
470
return class_name
477
471
return "%s.%s" % (module_name, class_name)
480
474
def report_exception(exc_info, err_file):
481
"""Report an exception to err_file (typically stderr) and to brz.log.
475
"""Report an exception to err_file (typically stderr) and to .bzr.log.
483
477
This will show either a full traceback or a short message as appropriate.
485
479
:return: The appropriate exit code for this error.
487
# Log the full traceback to brz.log
481
# Log the full traceback to ~/.bzr.log
488
482
log_exception_quietly()
489
483
if 'error' in debug.debug_flags:
490
484
print_exception(exc_info, err_file)
491
485
return errors.EXIT_ERROR
492
486
exc_type, exc_object, exc_tb = exc_info
493
487
if isinstance(exc_object, KeyboardInterrupt):
494
err_file.write("brz: interrupted\n")
488
err_file.write("bzr: interrupted\n")
495
489
return errors.EXIT_ERROR
496
490
elif isinstance(exc_object, MemoryError):
497
err_file.write("brz: out of memory\n")
491
err_file.write("bzr: out of memory\n")
498
492
if 'mem_dump' in debug.debug_flags:
499
493
_dump_memory_usage(err_file)
501
495
err_file.write("Use -Dmem_dump to dump memory to a file.\n")
502
496
return errors.EXIT_ERROR
503
497
elif isinstance(exc_object, ImportError) \
504
and str(exc_object).startswith("No module named "):
498
and str(exc_object).startswith("No module named "):
499
report_user_error(exc_info, err_file,
507
500
'You may need to install this Python library separately.')
508
501
return errors.EXIT_ERROR
509
502
elif not getattr(exc_object, 'internal_error', True):
511
504
return errors.EXIT_ERROR
512
505
elif osutils.is_environment_error(exc_object):
513
506
if getattr(exc_object, 'errno', None) == errno.EPIPE:
514
err_file.write("brz: broken pipe\n")
507
err_file.write("bzr: broken pipe\n")
515
508
return errors.EXIT_ERROR
516
509
# Might be nice to catch all of these and show them as something more
517
510
# specific, but there are too many cases at the moment.
525
518
def print_exception(exc_info, err_file):
526
519
exc_type, exc_object, exc_tb = exc_info
527
err_file.write("brz: ERROR: %s: %s\n" % (
528
_qualified_exception_name(exc_type), exc_object))
520
err_file.write("bzr: ERROR: %s.%s: %s\n" % (
521
exc_type.__module__, exc_type.__name__, exc_object))
529
522
err_file.write('\n')
530
523
traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
540
533
:param advice: Extra advice to the user to be printed following the
543
err_file.write(("brz: ERROR: %s\n" % (str(exc_info[1]),)))
536
err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
545
err_file.write(("%s\n" % advice))
538
err_file.write("%s\n" % (advice,))
548
541
def report_bug(exc_info, err_file):
549
"""Report an exception that probably indicates a bug in brz"""
550
from breezy.crash import report_bug
542
"""Report an exception that probably indicates a bug in bzr"""
543
from brzlib.crash import report_bug
551
544
report_bug(exc_info, err_file)
554
547
def _flush_stdout_stderr():
555
# called from the breezy library finalizer returned by breezy.initialize()
548
# called from the brzlib library finalizer returned by brzlib.initialize()
557
550
sys.stdout.flush()
558
551
sys.stderr.flush()
552
except ValueError, e:
560
553
# On Windows, I get ValueError calling stdout.flush() on a closed
565
558
if e.errno in [errno.EINVAL, errno.EPIPE]:
601
594
def emit(self, record):
603
if not isinstance(record.msg, str):
604
msg = record.msg.decode("utf-8")
606
596
line = self.format(record)
607
if not isinstance(line, str):
597
if not isinstance(line, unicode):
608
598
line = line.decode("utf-8")
609
self.stream.write(line.encode(self.encoding, self.errors) + b"\n")
599
self.stream.write(line.encode(self.encoding, self.errors) + "\n")
610
600
except Exception:
611
601
log_exception_quietly()
612
602
# Try saving the details that would have been logged in some form
613
603
msg = args = "<Unformattable>"
615
msg = repr(record.msg)
616
args = repr(record.args)
605
msg = repr(record.msg).encode("ascii")
606
args = repr(record.args).encode("ascii")
617
607
except Exception:
619
609
# Using mutter() bypasses the logging module and writes directly
624
614
class Config(object):
625
"""Configuration of message tracing in breezy.
615
"""Configuration of message tracing in brzlib.
627
617
This implements the context manager protocol and should manage any global
628
618
variables still used. The default config used is DefaultConfig, but
629
embedded uses of breezy may wish to use a custom manager.
619
embedded uses of brzlib may wish to use a custom manager.
632
622
def __enter__(self):
633
return self # This is bound to the 'as' clause in a with statement.
623
return self # This is bound to the 'as' clause in a with statement.
635
625
def __exit__(self, exc_type, exc_val, exc_tb):
636
return False # propogate exceptions.
626
return False # propogate exceptions.
639
629
class DefaultConfig(Config):
640
"""A default configuration for tracing of messages in breezy.
630
"""A default configuration for tracing of messages in brzlib.
642
632
This implements the context manager protocol.
645
635
def __enter__(self):
646
self._original_filename = _brz_log_filename
636
self._original_filename = _bzr_log_filename
647
637
self._original_state = enable_default_logging()
648
return self # This is bound to the 'as' clause in a with statement.
638
return self # This is bound to the 'as' clause in a with statement.
650
640
def __exit__(self, exc_type, exc_val, exc_tb):
651
641
pop_log_file(self._original_state)
652
global _brz_log_filename
653
_brz_log_filename = self._original_filename
654
return False # propogate exceptions.
642
global _bzr_log_filename
643
_bzr_log_filename = self._original_filename
644
return False # propogate exceptions.
added
removed
brzlib/trace.py
