23
23
Messages are classified by severity levels: critical, error, warning, info,
 
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.
 
 
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.
 
30
 
~/.bzr.log gets all messages, and full tracebacks for uncaught exceptions.
 
 
30
`brz.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
 
63
 
from bzrlib.lazy_import import lazy_import
 
 
65
from .lazy_import import lazy_import
 
64
66
lazy_import(globals(), """
 
65
 
from cStringIO import StringIO
 
73
 
from bzrlib.symbol_versioning import (
 
78
73
lazy_import(globals(), """
 
90
 
# global verbosity for bzrlib; controls the log level for stderr; 0=normal; <0
 
 
92
# global verbosity for breezy; controls the log level for stderr; 0=normal; <0
 
91
93
# is quiet; >0 is verbose.
 
92
94
_verbosity_level = 0
 
 
97
99
# than push/pop_log_file.
 
98
100
_trace_file = None
 
100
 
# Absolute path for ~/.bzr.log.  Not changed even if the log/trace output is
 
 
102
# Absolute path for brz.log.  Not changed even if the log/trace output is
 
101
103
# redirected elsewhere.  Used to show the location in --version.
 
102
 
_bzr_log_filename = None
 
 
104
_brz_log_filename = None
 
104
106
# The time the first message was written to the trace file, so that we can
 
105
107
# show relative times since startup.
 
106
 
_bzr_log_start_time = bzrlib._start_time
 
 
108
_brz_log_start_time = breezy._start_time
 
109
111
# held in a global for quick reference
 
110
 
_bzr_logger = logging.getLogger('bzr')
 
 
112
_brz_logger = logging.getLogger('brz')
 
113
115
def note(*args, **kwargs):
 
114
 
    # FIXME note always emits utf-8, regardless of the terminal encoding
 
 
116
    """Output a note to the user.
 
 
118
    Takes the same parameters as logging.info.
 
116
122
    # FIXME: clearing the ui and then going through the abstract logging
 
117
123
    # framework is whack; we should probably have a logging Handler that
 
118
124
    # deals with terminal output if needed.
 
120
 
    bzrlib.ui.ui_factory.clear_term()
 
121
 
    _bzr_logger.info(*args, **kwargs)
 
 
125
    ui.ui_factory.clear_term()
 
 
126
    _brz_logger.info(*args, **kwargs)
 
124
129
def warning(*args, **kwargs):
 
126
 
    bzrlib.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)
 
 
130
    ui.ui_factory.clear_term()
 
 
131
    _brz_logger.warning(*args, **kwargs)
 
148
134
def show_error(*args, **kwargs):
 
 
161
157
    if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
 
164
 
    if isinstance(fmt, unicode):
 
165
 
        fmt = fmt.encode('utf8')
 
 
160
    # Let format strings be specified as ascii bytes to help Python 2
 
 
161
    if isinstance(fmt, bytes):
 
 
162
        fmt = fmt.decode('ascii', 'replace')
 
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)
 
 
167
                _Bytes(arg) if isinstance(arg, bytes) else arg for arg in args)
 
179
171
    now = time.time()
 
180
 
    timestamp = '%0.3f  ' % (now - _bzr_log_start_time,)
 
181
 
    out = timestamp + out + '\n'
 
182
 
    _trace_file.write(out)
 
 
172
    out = '%0.3f  %s\n' % (now - _brz_log_start_time, out)
 
 
173
    _trace_file.write(out.encode('utf-8'))
 
183
174
    # there's no explicit flushing; the file is typically line buffered.
 
 
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.
 
 
208
def _get_brz_log_filename():
 
 
209
    """Return the brz log filename.
 
 
211
    :return: A path to the log file
 
 
212
    :raise EnvironmentError: If the cache directory could not be created
 
 
214
    brz_log = osutils.path_from_environ('BRZ_LOG')
 
 
217
    return os.path.join(bedding.cache_dir(), 'brz.log')
 
 
221
    """Open the brz.log trace file.
 
234
223
    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
 
 
224
    brz.log.old and a new file is started.  Otherwise, we append to the
 
238
 
    This sets the global _bzr_log_filename.
 
 
227
    This sets the global _brz_log_filename.
 
240
 
    global _bzr_log_filename
 
 
229
    global _brz_log_filename
 
242
231
    def _open_or_create_log_file(filename):
 
243
232
        """Open existing log file, or create with ownership and permissions
 
 
252
241
                fd = os.open(filename, flags)
 
255
244
                if e.errno != errno.ENOENT:
 
258
 
                fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0666)
 
 
247
                fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0o666)
 
260
249
                if e.errno != errno.EEXIST:
 
263
252
                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)
 
 
254
        return os.fdopen(fd, 'ab', 0)  # unbuffered
 
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:
 
 
257
        _brz_log_filename = _get_brz_log_filename()
 
 
258
        _rollover_trace_maybe(_brz_log_filename)
 
 
260
        brz_log_file = _open_or_create_log_file(_brz_log_filename)
 
 
261
        brz_log_file.write(b'\n')
 
 
262
        if brz_log_file.tell() <= 2:
 
 
264
                b"this is a debug log for diagnosing/reporting problems in brz\n")
 
 
266
                b"you can delete or truncate this file, or include sections in\n")
 
 
268
                b"bug reports to https://bugs.launchpad.net/brz/+filebug\n\n")
 
 
272
    except EnvironmentError as e:
 
281
273
        # If we are failing to open the log, then most likely logging has not
 
282
274
        # been set up yet. So we just write to stderr rather than using
 
283
275
        # 'warning()'. If we using warning(), users get the unhelpful 'no
 
284
 
        # handlers registered for "bzr"' when something goes wrong on the
 
 
276
        # handlers registered for "brz"' when something goes wrong on the
 
285
277
        # server. (bug #503886)
 
286
278
        sys.stderr.write("failed to open trace file: %s\n" % (e,))
 
287
279
    # TODO: What should happen if we fail to open the trace file?  Maybe the
 
 
293
285
def enable_default_logging():
 
294
 
    """Configure default logging: messages to stderr and debug to .bzr.log
 
 
286
    """Configure default logging: messages to stderr and debug to brz.log
 
296
288
    This should only be called once per process.
 
298
 
    Non-command-line programs embedding bzrlib do not need to call this.  They
 
 
290
    Non-command-line programs embedding breezy do not need to call this.  They
 
299
291
    can instead either pass a file to _push_log_file, or act directly on
 
300
 
    logging.getLogger("bzr").
 
 
292
    logging.getLogger("brz").
 
302
294
    Output can be redirected away by calling _push_log_file.
 
 
296
    :return: A memento from push_log_file for restoring the log state.
 
304
 
    # Do this before we open the log file, so we prevent
 
305
 
    # get_terminal_encoding() from mutter()ing multiple times
 
306
 
    term_encoding = osutils.get_terminal_encoding()
 
307
 
    start_time = osutils.format_local_date(_bzr_log_start_time,
 
 
298
    start_time = osutils.format_local_date(_brz_log_start_time,
 
308
299
                                           timezone='local')
 
309
 
    # create encoded wrapper around stderr
 
310
 
    bzr_log_file = _open_bzr_log()
 
311
 
    if bzr_log_file is not None:
 
312
 
        bzr_log_file.write(start_time.encode('utf-8') + '\n')
 
313
 
    push_log_file(bzr_log_file,
 
 
300
    brz_log_file = _open_brz_log()
 
 
301
    if brz_log_file is not None:
 
 
302
        brz_log_file.write(start_time.encode('utf-8') + b'\n')
 
 
303
    memento = push_log_file(
 
314
305
        r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
 
315
306
        r'%Y-%m-%d %H:%M:%S')
 
316
 
    # after hooking output into bzr_log, we also need to attach a stderr
 
 
307
    # after hooking output into brz_log, we also need to attach a stderr
 
317
308
    # handler, writing only at level info and with encoding
 
318
 
    writer_factory = codecs.getwriter(term_encoding)
 
319
 
    encoded_stderr = writer_factory(sys.stderr, errors='replace')
 
320
 
    stderr_handler = logging.StreamHandler(encoded_stderr)
 
321
 
    stderr_handler.setLevel(logging.INFO)
 
322
 
    logging.getLogger('bzr').addHandler(stderr_handler)
 
 
309
    if sys.version_info[0] == 2:
 
 
310
        stderr_handler = EncodedStreamHandler(
 
 
311
            sys.stderr, osutils.get_terminal_encoding(), 'replace',
 
 
314
        stderr_handler = logging.StreamHandler(stream=sys.stderr)
 
 
315
    logging.getLogger('brz').addHandler(stderr_handler)
 
325
319
def push_log_file(to_file, log_format=None, date_format=None):
 
 
328
322
    :param to_file: A file-like object to which messages will be sent.
 
330
324
    :returns: A memento that should be passed to _pop_log_file to restore the
 
331
 
    previously active logging.
 
 
325
        previously active logging.
 
333
327
    global _trace_file
 
334
328
    # make a new handler
 
335
 
    new_handler = logging.StreamHandler(to_file)
 
336
 
    new_handler.setLevel(logging.DEBUG)
 
 
329
    new_handler = EncodedStreamHandler(to_file, "utf-8", level=logging.DEBUG)
 
337
330
    if log_format is None:
 
338
331
        log_format = '%(levelname)8s  %(message)s'
 
339
332
    new_handler.setFormatter(logging.Formatter(log_format, date_format))
 
340
333
    # save and remove any existing log handlers
 
341
 
    bzr_logger = logging.getLogger('bzr')
 
342
 
    old_handlers = bzr_logger.handlers[:]
 
343
 
    del bzr_logger.handlers[:]
 
 
334
    brz_logger = logging.getLogger('brz')
 
 
335
    old_handlers = brz_logger.handlers[:]
 
 
336
    del brz_logger.handlers[:]
 
344
337
    # set that as the default logger
 
345
 
    bzr_logger.addHandler(new_handler)
 
346
 
    bzr_logger.setLevel(logging.DEBUG)
 
 
338
    brz_logger.addHandler(new_handler)
 
 
339
    brz_logger.setLevel(logging.DEBUG)
 
347
340
    # TODO: check if any changes are needed to the root logger
 
349
 
    # TODO: also probably need to save and restore the level on bzr_logger.
 
 
342
    # TODO: also probably need to save and restore the level on brz_logger.
 
350
343
    # but maybe we can avoid setting the logger level altogether, and just set
 
351
344
    # the level on the handler?
 
 
354
347
    old_trace_file = _trace_file
 
355
348
    # send traces to the new one
 
356
349
    _trace_file = to_file
 
357
 
    result = new_handler, _trace_file
 
358
350
    return ('log_memento', old_handlers, new_handler, old_trace_file, to_file)
 
361
 
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
 
 
353
def pop_log_file(entry):
 
362
354
    """Undo changes to logging/tracing done by _push_log_file.
 
364
 
    This flushes, but does not close the trace file.
 
 
356
    This flushes, but does not close the trace file (so that anything that was
 
366
359
    Takes the memento returned from _push_log_file."""
 
 
360
    (magic, old_handlers, new_handler, old_trace_file, new_trace_file) = entry
 
367
361
    global _trace_file
 
368
362
    _trace_file = old_trace_file
 
369
 
    bzr_logger = logging.getLogger('bzr')
 
370
 
    bzr_logger.removeHandler(new_handler)
 
371
 
    # must be closed, otherwise logging will try to close it atexit, and the
 
 
363
    brz_logger = logging.getLogger('brz')
 
 
364
    brz_logger.removeHandler(new_handler)
 
 
365
    # must be closed, otherwise logging will try to close it at exit, and the
 
372
366
    # file will likely already be closed underneath.
 
373
367
    new_handler.close()
 
374
 
    bzr_logger.handlers = old_handlers
 
375
 
    new_trace_file.flush()
 
 
368
    brz_logger.handlers = old_handlers
 
 
369
    if new_trace_file is not None:
 
 
370
        new_trace_file.flush()
 
378
373
def log_exception_quietly():
 
 
 
460
def _dump_memory_usage(err_file):
 
 
463
            fd, name = tempfile.mkstemp(prefix="brz_memdump", suffix=".json")
 
 
464
            dump_file = os.fdopen(fd, 'w')
 
 
465
            from meliae import scanner
 
 
466
            scanner.dump_gc_objects(dump_file)
 
 
467
            err_file.write("Memory dumped to %s\n" % name)
 
 
469
            err_file.write("Dumping memory requires meliae module.\n")
 
 
470
            log_exception_quietly()
 
 
471
        except BaseException:
 
 
472
            err_file.write("Exception while dumping memory.\n")
 
 
473
            log_exception_quietly()
 
 
475
        if dump_file is not None:
 
 
481
def _qualified_exception_name(eclass, unqualified_breezy_errors=False):
 
 
482
    """Give name of error class including module for non-builtin exceptions
 
 
484
    If `unqualified_breezy_errors` is True, errors specific to breezy will
 
 
485
    also omit the module prefix.
 
 
487
    class_name = eclass.__name__
 
 
488
    module_name = eclass.__module__
 
 
489
    if module_name in ("builtins", "exceptions", "__main__") or (
 
 
490
            unqualified_breezy_errors and module_name == "breezy.errors"):
 
 
492
    return "%s.%s" % (module_name, class_name)
 
464
495
def report_exception(exc_info, err_file):
 
465
 
    """Report an exception to err_file (typically stderr) and to .bzr.log.
 
 
496
    """Report an exception to err_file (typically stderr) and to brz.log.
 
467
498
    This will show either a full traceback or a short message as appropriate.
 
469
500
    :return: The appropriate exit code for this error.
 
471
 
    # Log the full traceback to ~/.bzr.log
 
 
502
    # Log the full traceback to brz.log
 
472
503
    log_exception_quietly()
 
473
504
    if 'error' in debug.debug_flags:
 
474
505
        print_exception(exc_info, err_file)
 
475
506
        return errors.EXIT_ERROR
 
476
507
    exc_type, exc_object, exc_tb = exc_info
 
477
 
    if (isinstance(exc_object, IOError)
 
478
 
        and getattr(exc_object, 'errno', None) == errno.EPIPE):
 
479
 
        err_file.write("bzr: broken pipe\n")
 
480
 
        return errors.EXIT_ERROR
 
481
 
    elif isinstance(exc_object, KeyboardInterrupt):
 
482
 
        err_file.write("bzr: interrupted\n")
 
 
508
    if isinstance(exc_object, KeyboardInterrupt):
 
 
509
        err_file.write("brz: interrupted\n")
 
483
510
        return errors.EXIT_ERROR
 
484
511
    elif isinstance(exc_object, MemoryError):
 
485
 
        err_file.write("bzr: out of memory\n")
 
 
512
        err_file.write("brz: out of memory\n")
 
 
513
        if 'mem_dump' in debug.debug_flags:
 
 
514
            _dump_memory_usage(err_file)
 
 
516
            err_file.write("Use -Dmem_dump to dump memory to a file.\n")
 
486
517
        return errors.EXIT_ERROR
 
487
518
    elif isinstance(exc_object, ImportError) \
 
488
 
        and str(exc_object).startswith("No module named "):
 
489
 
        report_user_error(exc_info, err_file,
 
 
519
            and str(exc_object).startswith("No module named "):
 
490
522
            'You may need to install this Python library separately.')
 
491
523
        return errors.EXIT_ERROR
 
492
524
    elif not getattr(exc_object, 'internal_error', True):
 
493
525
        report_user_error(exc_info, err_file)
 
494
526
        return errors.EXIT_ERROR
 
495
 
    elif isinstance(exc_object, (OSError, IOError)):
 
 
527
    elif osutils.is_environment_error(exc_object):
 
 
528
        if getattr(exc_object, 'errno', None) == errno.EPIPE:
 
 
529
            err_file.write("brz: broken pipe\n")
 
 
530
            return errors.EXIT_ERROR
 
496
531
        # Might be nice to catch all of these and show them as something more
 
497
532
        # specific, but there are too many cases at the moment.
 
498
533
        report_user_error(exc_info, err_file)
 
 
505
540
def print_exception(exc_info, err_file):
 
506
541
    exc_type, exc_object, exc_tb = exc_info
 
507
 
    err_file.write("bzr: ERROR: %s.%s: %s\n" % (
 
508
 
        exc_type.__module__, exc_type.__name__, exc_object))
 
 
542
    err_file.write("brz: ERROR: %s: %s\n" % (
 
 
543
        _qualified_exception_name(exc_type), exc_object))
 
509
544
    err_file.write('\n')
 
510
545
    traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
 
 
520
555
    :param advice: Extra advice to the user to be printed following the
 
523
 
    err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
 
 
558
    err_file.write(("brz: ERROR: %s\n" % (str(exc_info[1]),)))
 
525
 
        err_file.write("%s\n" % (advice,))
 
 
560
        err_file.write(("%s\n" % advice))
 
528
563
def report_bug(exc_info, err_file):
 
529
 
    """Report an exception that probably indicates a bug in bzr"""
 
530
 
    from bzrlib.crash import report_bug
 
 
564
    """Report an exception that probably indicates a bug in brz"""
 
 
565
    from breezy.crash import report_bug
 
531
566
    report_bug(exc_info, err_file)
 
534
569
def _flush_stdout_stderr():
 
535
 
    # installed into an atexit hook by bzrlib.initialize()
 
 
570
    # called from the breezy library finalizer returned by breezy.initialize()
 
537
572
        sys.stdout.flush()
 
538
573
        sys.stderr.flush()
 
 
575
        # On Windows, I get ValueError calling stdout.flush() on a closed
 
541
580
        if e.errno in [errno.EINVAL, errno.EPIPE]:
 
 
547
586
def _flush_trace():
 
548
 
    # run from atexit hook
 
 
587
    # called from the breezy library finalizer returned by breezy.initialize()
 
549
588
    global _trace_file
 
551
590
        _trace_file.flush()
 
 
593
class EncodedStreamHandler(logging.Handler):
 
 
594
    """Robustly write logging events to a stream using the specified encoding
 
 
596
    Messages are expected to be formatted to unicode, but UTF-8 byte strings
 
 
597
    are also accepted. An error during formatting or a str message in another
 
 
598
    encoding will be quitely noted as an error in the Bazaar log file.
 
 
600
    The stream is not closed so sys.stdout or sys.stderr may be passed.
 
 
603
    def __init__(self, stream, encoding=None, errors='strict', level=0):
 
 
604
        logging.Handler.__init__(self, level)
 
 
607
            encoding = getattr(stream, "encoding", "ascii")
 
 
608
        self.encoding = encoding
 
 
612
        flush = getattr(self.stream, "flush", None)
 
 
613
        if flush is not None:
 
 
616
    def emit(self, record):
 
 
618
            if not isinstance(record.msg, text_type):
 
 
619
                msg = record.msg.decode("utf-8")
 
 
622
            line = self.format(record)
 
 
623
            if not isinstance(line, text_type):
 
 
624
                line = line.decode("utf-8")
 
 
625
            self.stream.write(line.encode(self.encoding, self.errors) + b"\n")
 
 
627
            log_exception_quietly()
 
 
628
            # Try saving the details that would have been logged in some form
 
 
629
            msg = args = "<Unformattable>"
 
 
631
                msg = repr(record.msg)
 
 
632
                args = repr(record.args)
 
 
635
            # Using mutter() bypasses the logging module and writes directly
 
 
636
            # to the file so there's no danger of getting into a loop here.
 
 
637
            mutter("Logging record unformattable: %s %% %s", msg, args)
 
 
640
class Config(object):
 
 
641
    """Configuration of message tracing in breezy.
 
 
643
    This implements the context manager protocol and should manage any global
 
 
644
    variables still used. The default config used is DefaultConfig, but
 
 
645
    embedded uses of breezy may wish to use a custom manager.
 
 
649
        return self  # This is bound to the 'as' clause in a with statement.
 
 
651
    def __exit__(self, exc_type, exc_val, exc_tb):
 
 
652
        return False  # propogate exceptions.
 
 
655
class DefaultConfig(Config):
 
 
656
    """A default configuration for tracing of messages in breezy.
 
 
658
    This implements the context manager protocol.
 
 
662
        self._original_filename = _brz_log_filename
 
 
663
        self._original_state = enable_default_logging()
 
 
664
        return self  # This is bound to the 'as' clause in a with statement.
 
 
666
    def __exit__(self, exc_type, exc_val, exc_tb):
 
 
667
        pop_log_file(self._original_state)
 
 
668
        global _brz_log_filename
 
 
669
        _brz_log_filename = self._original_filename
 
 
670
        return False  # propogate exceptions.