/breezy/unstable

To get this branch, use:
bzr branch https://code.breezy-vcs.org/breezy/unstable

« back to all changes in this revision

Viewing changes to breezy/trace.py

  • Committer: Jelmer Vernooij
  • Date: 2017-05-24 01:39:33 UTC
  • mfrom: (3815.3776.6)
  • Revision ID: jelmer@jelmer.uk-20170524013933-ir4y4tqtrsiz2ka2
New upstream snapshot.

Show diffs side-by-side

added added

removed removed

Lines of Context:
23
23
Messages are classified by severity levels: critical, error, warning, info,
24
24
and debug.
25
25
 
26
 
They can be sent to two places: to stderr, and to ~/.bzr.log.  For purposes
 
26
They can be sent to two places: to stderr, and to ~/.brz.log.  For purposes
27
27
such as running the test suite, they can also be redirected away from both of
28
28
those two places to another location.
29
29
 
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.
33
33
 
56
56
# increased cost of logging.py is not so bad, and we could standardize on
57
57
# that.
58
58
 
 
59
import errno
59
60
import logging
60
61
import os
61
62
import sys
62
63
import time
63
64
 
64
 
from bzrlib.lazy_import import lazy_import
 
65
from .lazy_import import lazy_import
65
66
lazy_import(globals(), """
66
 
from cStringIO import StringIO
67
 
import errno
68
67
import locale
69
68
import tempfile
70
69
import traceback
71
70
""")
72
71
 
73
 
import bzrlib
 
72
import breezy
74
73
 
75
74
lazy_import(globals(), """
76
 
from bzrlib import (
 
75
from breezy import (
77
76
    debug,
78
77
    errors,
79
78
    osutils,
81
80
    )
82
81
""")
83
82
 
84
 
 
85
 
# global verbosity for bzrlib; controls the log level for stderr; 0=normal; <0
 
83
from .sixish import (
 
84
    BytesIO,
 
85
    text_type,
 
86
    )
 
87
 
 
88
 
 
89
# global verbosity for breezy; controls the log level for stderr; 0=normal; <0
86
90
# is quiet; >0 is verbose.
87
91
_verbosity_level = 0
88
92
 
92
96
# than push/pop_log_file.
93
97
_trace_file = None
94
98
 
95
 
# Absolute path for ~/.bzr.log.  Not changed even if the log/trace output is
 
99
# Absolute path for ~/.brz.log.  Not changed even if the log/trace output is
96
100
# redirected elsewhere.  Used to show the location in --version.
97
 
_bzr_log_filename = None
 
101
_brz_log_filename = None
98
102
 
99
103
# The time the first message was written to the trace file, so that we can
100
104
# show relative times since startup.
101
 
_bzr_log_start_time = bzrlib._start_time
 
105
_brz_log_start_time = breezy._start_time
102
106
 
103
107
 
104
108
# held in a global for quick reference
105
 
_bzr_logger = logging.getLogger('bzr')
 
109
_brz_logger = logging.getLogger('brz')
106
110
 
107
111
 
108
112
def note(*args, **kwargs):
116
120
    # framework is whack; we should probably have a logging Handler that
117
121
    # deals with terminal output if needed.
118
122
    ui.ui_factory.clear_term()
119
 
    _bzr_logger.info(*args, **kwargs)
 
123
    _brz_logger.info(*args, **kwargs)
120
124
 
121
125
 
122
126
def warning(*args, **kwargs):
123
127
    ui.ui_factory.clear_term()
124
 
    _bzr_logger.warning(*args, **kwargs)
 
128
    _brz_logger.warning(*args, **kwargs)
125
129
 
126
130
 
127
131
def show_error(*args, **kwargs):
129
133
 
130
134
    Don't use this for exceptions, use report_exception instead.
131
135
    """
132
 
    _bzr_logger.error(*args, **kwargs)
 
136
    _brz_logger.error(*args, **kwargs)
133
137
 
134
138
 
135
139
def mutter(fmt, *args):
140
144
    if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
141
145
        return
142
146
 
143
 
    if isinstance(fmt, unicode):
 
147
    if isinstance(fmt, text_type):
144
148
        fmt = fmt.encode('utf8')
145
149
 
146
150
    if len(args) > 0:
149
153
        # is a unicode string
150
154
        real_args = []
151
155
        for arg in args:
152
 
            if isinstance(arg, unicode):
 
156
            if isinstance(arg, text_type):
153
157
                arg = arg.encode('utf8')
154
158
            real_args.append(arg)
155
159
        out = fmt % tuple(real_args)
156
160
    else:
157
161
        out = fmt
158
162
    now = time.time()
159
 
    timestamp = '%0.3f  ' % (now - _bzr_log_start_time,)
160
 
    out = timestamp + out + '\n'
 
163
    out = b'%0.3f  %s\n' % (now - _brz_log_start_time, out)
161
164
    _trace_file.write(out)
162
165
    # there's no explicit flushing; the file is typically line buffered.
163
166
 
170
173
    :param fmt: The format string to pass to mutter.
171
174
    :param args: A list of substitution variables.
172
175
    """
173
 
    outf = StringIO()
 
176
    outf = BytesIO()
174
177
    if stacklevel is None:
175
178
        limit = None
176
179
    else:
193
196
        return
194
197
 
195
198
 
196
 
def _get_bzr_log_filename():
197
 
    bzr_log = osutils.path_from_environ('BZR_LOG')
198
 
    if bzr_log:
199
 
        return bzr_log
200
 
    home = osutils.path_from_environ('BZR_HOME')
 
199
def _get_brz_log_filename():
 
200
    brz_log = osutils.path_from_environ('BRZ_LOG')
 
201
    if brz_log:
 
202
        return brz_log
 
203
    home = osutils.path_from_environ('BRZ_HOME')
201
204
    if home is None:
202
205
        # GZ 2012-02-01: Logging to the home dir is bad, but XDG is unclear
203
206
        #                over what would be better. On windows, bug 240550
204
207
        #                suggests LOCALAPPDATA be used instead.
205
208
        home = osutils._get_home_dir()
206
 
    return os.path.join(home, '.bzr.log')
207
 
 
208
 
 
209
 
def _open_bzr_log():
210
 
    """Open the .bzr.log trace file.
 
209
    return os.path.join(home, '.brz.log')
 
210
 
 
211
 
 
212
def _open_brz_log():
 
213
    """Open the .brz.log trace file.
211
214
 
212
215
    If the log is more than a particular length, the old file is renamed to
213
 
    .bzr.log.old and a new file is started.  Otherwise, we append to the
 
216
    .brz.log.old and a new file is started.  Otherwise, we append to the
214
217
    existing file.
215
218
 
216
 
    This sets the global _bzr_log_filename.
 
219
    This sets the global _brz_log_filename.
217
220
    """
218
 
    global _bzr_log_filename
 
221
    global _brz_log_filename
219
222
 
220
223
    def _open_or_create_log_file(filename):
221
224
        """Open existing log file, or create with ownership and permissions
229
232
            try:
230
233
                fd = os.open(filename, flags)
231
234
                break
232
 
            except OSError, e:
 
235
            except OSError as e:
233
236
                if e.errno != errno.ENOENT:
234
237
                    raise
235
238
            try:
236
 
                fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0666)
237
 
            except OSError, e:
 
239
                fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0o666)
 
240
            except OSError as e:
238
241
                if e.errno != errno.EEXIST:
239
242
                    raise
240
243
            else:
241
244
                osutils.copy_ownership_from_path(filename)
242
245
                break
243
 
        return os.fdopen(fd, 'at', 0) # unbuffered
244
 
 
245
 
 
246
 
    _bzr_log_filename = _get_bzr_log_filename()
247
 
    _rollover_trace_maybe(_bzr_log_filename)
 
246
        return os.fdopen(fd, 'ab', 0) # unbuffered
 
247
 
 
248
 
 
249
    _brz_log_filename = _get_brz_log_filename()
 
250
    _rollover_trace_maybe(_brz_log_filename)
248
251
    try:
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")
255
 
 
256
 
        return bzr_log_file
257
 
 
258
 
    except EnvironmentError, e:
 
252
        brz_log_file = _open_or_create_log_file(_brz_log_filename)
 
253
        brz_log_file.write(b'\n')
 
254
        if brz_log_file.tell() <= 2:
 
255
            brz_log_file.write("this is a debug log for diagnosing/reporting problems in brz\n")
 
256
            brz_log_file.write("you can delete or truncate this file, or include sections in\n")
 
257
            brz_log_file.write("bug reports to https://bugs.launchpad.net/brz/+filebug\n\n")
 
258
 
 
259
        return brz_log_file
 
260
 
 
261
    except EnvironmentError as e:
259
262
        # If we are failing to open the log, then most likely logging has not
260
263
        # been set up yet. So we just write to stderr rather than using
261
264
        # 'warning()'. If we using warning(), users get the unhelpful 'no
262
 
        # handlers registered for "bzr"' when something goes wrong on the
 
265
        # handlers registered for "brz"' when something goes wrong on the
263
266
        # server. (bug #503886)
264
267
        sys.stderr.write("failed to open trace file: %s\n" % (e,))
265
268
    # TODO: What should happen if we fail to open the trace file?  Maybe the
269
272
 
270
273
 
271
274
def enable_default_logging():
272
 
    """Configure default logging: messages to stderr and debug to .bzr.log
 
275
    """Configure default logging: messages to stderr and debug to .brz.log
273
276
 
274
277
    This should only be called once per process.
275
278
 
276
 
    Non-command-line programs embedding bzrlib do not need to call this.  They
 
279
    Non-command-line programs embedding breezy do not need to call this.  They
277
280
    can instead either pass a file to _push_log_file, or act directly on
278
 
    logging.getLogger("bzr").
 
281
    logging.getLogger("brz").
279
282
 
280
283
    Output can be redirected away by calling _push_log_file.
281
284
 
282
285
    :return: A memento from push_log_file for restoring the log state.
283
286
    """
284
 
    start_time = osutils.format_local_date(_bzr_log_start_time,
 
287
    start_time = osutils.format_local_date(_brz_log_start_time,
285
288
                                           timezone='local')
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,
 
289
    brz_log_file = _open_brz_log()
 
290
    if brz_log_file is not None:
 
291
        brz_log_file.write(start_time.encode('utf-8') + b'\n')
 
292
    memento = push_log_file(brz_log_file,
290
293
        r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
291
294
        r'%Y-%m-%d %H:%M:%S')
292
 
    # after hooking output into bzr_log, we also need to attach a stderr
 
295
    # after hooking output into brz_log, we also need to attach a stderr
293
296
    # handler, writing only at level info and with encoding
294
297
    stderr_handler = EncodedStreamHandler(sys.stderr,
295
298
        osutils.get_terminal_encoding(), 'replace', level=logging.INFO)
296
 
    logging.getLogger('bzr').addHandler(stderr_handler)
 
299
    logging.getLogger('brz').addHandler(stderr_handler)
297
300
    return memento
298
301
 
299
302
 
312
315
        log_format = '%(levelname)8s  %(message)s'
313
316
    new_handler.setFormatter(logging.Formatter(log_format, date_format))
314
317
    # save and remove any existing log handlers
315
 
    bzr_logger = logging.getLogger('bzr')
316
 
    old_handlers = bzr_logger.handlers[:]
317
 
    del bzr_logger.handlers[:]
 
318
    brz_logger = logging.getLogger('brz')
 
319
    old_handlers = brz_logger.handlers[:]
 
320
    del brz_logger.handlers[:]
318
321
    # set that as the default logger
319
 
    bzr_logger.addHandler(new_handler)
320
 
    bzr_logger.setLevel(logging.DEBUG)
 
322
    brz_logger.addHandler(new_handler)
 
323
    brz_logger.setLevel(logging.DEBUG)
321
324
    # TODO: check if any changes are needed to the root logger
322
325
    #
323
 
    # TODO: also probably need to save and restore the level on bzr_logger.
 
326
    # TODO: also probably need to save and restore the level on brz_logger.
324
327
    # but maybe we can avoid setting the logger level altogether, and just set
325
328
    # the level on the handler?
326
329
    #
332
335
    return ('log_memento', old_handlers, new_handler, old_trace_file, to_file)
333
336
 
334
337
 
335
 
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
 
338
def pop_log_file(entry):
336
339
    """Undo changes to logging/tracing done by _push_log_file.
337
340
 
338
341
    This flushes, but does not close the trace file (so that anything that was
339
342
    in it is output.
340
343
 
341
344
    Takes the memento returned from _push_log_file."""
 
345
    (magic, old_handlers, new_handler, old_trace_file, new_trace_file) = entry
342
346
    global _trace_file
343
347
    _trace_file = old_trace_file
344
 
    bzr_logger = logging.getLogger('bzr')
345
 
    bzr_logger.removeHandler(new_handler)
 
348
    brz_logger = logging.getLogger('brz')
 
349
    brz_logger.removeHandler(new_handler)
346
350
    # must be closed, otherwise logging will try to close it at exit, and the
347
351
    # file will likely already be closed underneath.
348
352
    new_handler.close()
349
 
    bzr_logger.handlers = old_handlers
 
353
    brz_logger.handlers = old_handlers
350
354
    if new_trace_file is not None:
351
355
        new_trace_file.flush()
352
356
 
390
394
def _update_logging_level(quiet=True):
391
395
    """Hide INFO messages if quiet."""
392
396
    if quiet:
393
 
        _bzr_logger.setLevel(logging.WARNING)
 
397
        _brz_logger.setLevel(logging.WARNING)
394
398
    else:
395
 
        _bzr_logger.setLevel(logging.INFO)
 
399
        _brz_logger.setLevel(logging.INFO)
396
400
 
397
401
 
398
402
def is_quiet():
408
412
def debug_memory(message='', short=True):
409
413
    """Write out a memory dump."""
410
414
    if sys.platform == 'win32':
411
 
        from bzrlib import win32utils
 
415
        from breezy import win32utils
412
416
        win32utils.debug_memory_win32api(message=message, short=short)
413
417
    else:
414
418
        _debug_memory_proc(message=message, short=short)
439
443
def _dump_memory_usage(err_file):
440
444
    try:
441
445
        try:
442
 
            fd, name = tempfile.mkstemp(prefix="bzr_memdump", suffix=".json")
 
446
            fd, name = tempfile.mkstemp(prefix="brz_memdump", suffix=".json")
443
447
            dump_file = os.fdopen(fd, 'w')
444
448
            from meliae import scanner
445
449
            scanner.dump_gc_objects(dump_file)
457
461
            os.close(fd)
458
462
 
459
463
 
460
 
def _qualified_exception_name(eclass, unqualified_bzrlib_errors=False):
 
464
def _qualified_exception_name(eclass, unqualified_breezy_errors=False):
461
465
    """Give name of error class including module for non-builtin exceptions
462
466
 
463
 
    If `unqualified_bzrlib_errors` is True, errors specific to bzrlib will
 
467
    If `unqualified_breezy_errors` is True, errors specific to breezy will
464
468
    also omit the module prefix.
465
469
    """
466
470
    class_name = eclass.__name__
467
471
    module_name = eclass.__module__
468
472
    if module_name in ("exceptions", "__main__") or (
469
 
            unqualified_bzrlib_errors and module_name == "bzrlib.errors"):
 
473
            unqualified_breezy_errors and module_name == "breezy.errors"):
470
474
        return class_name
471
475
    return "%s.%s" % (module_name, class_name)
472
476
 
473
477
 
474
478
def report_exception(exc_info, err_file):
475
 
    """Report an exception to err_file (typically stderr) and to .bzr.log.
 
479
    """Report an exception to err_file (typically stderr) and to .brz.log.
476
480
 
477
481
    This will show either a full traceback or a short message as appropriate.
478
482
 
479
483
    :return: The appropriate exit code for this error.
480
484
    """
481
 
    # Log the full traceback to ~/.bzr.log
 
485
    # Log the full traceback to ~/.brz.log
482
486
    log_exception_quietly()
483
487
    if 'error' in debug.debug_flags:
484
488
        print_exception(exc_info, err_file)
485
489
        return errors.EXIT_ERROR
486
490
    exc_type, exc_object, exc_tb = exc_info
487
491
    if isinstance(exc_object, KeyboardInterrupt):
488
 
        err_file.write("bzr: interrupted\n")
 
492
        err_file.write("brz: interrupted\n")
489
493
        return errors.EXIT_ERROR
490
494
    elif isinstance(exc_object, MemoryError):
491
 
        err_file.write("bzr: out of memory\n")
 
495
        err_file.write("brz: out of memory\n")
492
496
        if 'mem_dump' in debug.debug_flags:
493
497
            _dump_memory_usage(err_file)
494
498
        else:
504
508
        return errors.EXIT_ERROR
505
509
    elif osutils.is_environment_error(exc_object):
506
510
        if getattr(exc_object, 'errno', None) == errno.EPIPE:
507
 
            err_file.write("bzr: broken pipe\n")
 
511
            err_file.write("brz: broken pipe\n")
508
512
            return errors.EXIT_ERROR
509
513
        # Might be nice to catch all of these and show them as something more
510
514
        # specific, but there are too many cases at the moment.
517
521
 
518
522
def print_exception(exc_info, err_file):
519
523
    exc_type, exc_object, exc_tb = exc_info
520
 
    err_file.write("bzr: ERROR: %s.%s: %s\n" % (
 
524
    err_file.write("brz: ERROR: %s.%s: %s\n" % (
521
525
        exc_type.__module__, exc_type.__name__, exc_object))
522
526
    err_file.write('\n')
523
527
    traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
533
537
    :param advice: Extra advice to the user to be printed following the
534
538
        exception.
535
539
    """
536
 
    err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
 
540
    err_file.write("brz: ERROR: %s\n" % (exc_info[1],))
537
541
    if advice:
538
542
        err_file.write("%s\n" % (advice,))
539
543
 
540
544
 
541
545
def report_bug(exc_info, err_file):
542
 
    """Report an exception that probably indicates a bug in bzr"""
543
 
    from bzrlib.crash import report_bug
 
546
    """Report an exception that probably indicates a bug in brz"""
 
547
    from breezy.crash import report_bug
544
548
    report_bug(exc_info, err_file)
545
549
 
546
550
 
547
551
def _flush_stdout_stderr():
548
 
    # called from the bzrlib library finalizer returned by bzrlib.initialize()
 
552
    # called from the breezy library finalizer returned by breezy.initialize()
549
553
    try:
550
554
        sys.stdout.flush()
551
555
        sys.stderr.flush()
552
 
    except ValueError, e:
 
556
    except ValueError as e:
553
557
        # On Windows, I get ValueError calling stdout.flush() on a closed
554
558
        # handle
555
559
        pass
556
 
    except IOError, e:
 
560
    except IOError as e:
557
561
        import errno
558
562
        if e.errno in [errno.EINVAL, errno.EPIPE]:
559
563
            pass
562
566
 
563
567
 
564
568
def _flush_trace():
565
 
    # called from the bzrlib library finalizer returned by bzrlib.initialize()
 
569
    # called from the breezy library finalizer returned by breezy.initialize()
566
570
    global _trace_file
567
571
    if _trace_file:
568
572
        _trace_file.flush()
594
598
    def emit(self, record):
595
599
        try:
596
600
            line = self.format(record)
597
 
            if not isinstance(line, unicode):
 
601
            if not isinstance(line, text_type):
598
602
                line = line.decode("utf-8")
599
 
            self.stream.write(line.encode(self.encoding, self.errors) + "\n")
 
603
            self.stream.write(line.encode(self.encoding, self.errors) + b"\n")
600
604
        except Exception:
601
605
            log_exception_quietly()
602
606
            # Try saving the details that would have been logged in some form
612
616
 
613
617
 
614
618
class Config(object):
615
 
    """Configuration of message tracing in bzrlib.
 
619
    """Configuration of message tracing in breezy.
616
620
 
617
621
    This implements the context manager protocol and should manage any global
618
622
    variables still used. The default config used is DefaultConfig, but
619
 
    embedded uses of bzrlib may wish to use a custom manager.
 
623
    embedded uses of breezy may wish to use a custom manager.
620
624
    """
621
625
 
622
626
    def __enter__(self):
627
631
 
628
632
 
629
633
class DefaultConfig(Config):
630
 
    """A default configuration for tracing of messages in bzrlib.
 
634
    """A default configuration for tracing of messages in breezy.
631
635
 
632
636
    This implements the context manager protocol.
633
637
    """
634
638
 
635
639
    def __enter__(self):
636
 
        self._original_filename = _bzr_log_filename
 
640
        self._original_filename = _brz_log_filename
637
641
        self._original_state = enable_default_logging()
638
642
        return self # This is bound to the 'as' clause in a with statement.
639
643
 
640
644
    def __exit__(self, exc_type, exc_val, exc_tb):
641
645
        pop_log_file(self._original_state)
642
 
        global _bzr_log_filename
643
 
        _bzr_log_filename = self._original_filename
 
646
        global _brz_log_filename
 
647
        _brz_log_filename = self._original_filename
644
648
        return False # propogate exceptions.