← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to bzrlib/trace.py

  • Committer: Vincent Ladeuil
  • Date: 2011-09-09 13:30:12 UTC
  • mfrom: (5609.48.11 2.3)
  • mto: (6015.33.3 2.4)
  • mto: This revision was merged to the branch mainline in revision 6134.
  • Revision ID: v.ladeuil+lp@free.fr-20110909133012-jc1d1zyqgak57123
Merge 2.3 into 2.4

Show diffs side-by-side

added added

removed removed

Lines of Context:
bzrlib/trace.py
1
 
# Copyright (C) 2005, 2006, 2007, 2008 Canonical Ltd
 
1
# Copyright (C) 2005-2011 Canonical Ltd
2
2
#
3
3
# This program is free software; you can redistribute it and/or modify
4
4
# it under the terms of the GNU General Public License as published by
14
14
# along with this program; if not, write to the Free Software
15
15
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
16
16
 
17
 
"""Messages and logging for bazaar-ng.
 
17
"""Messages and logging.
18
18
 
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
33
33
 
34
34
Output to stderr depends on the mode chosen by the user.  By default, messages
35
35
of info and above are sent out, which results in progress messages such as the
36
 
list of files processed by add and commit.  In quiet mode, only warnings and
37
 
above are shown.  In debug mode, stderr gets debug messages too.
 
36
list of files processed by add and commit.  In debug mode, stderr gets debug messages too.
38
37
 
39
38
Errors that terminate an operation are generally passed back as exceptions;
40
39
others may be just emitted as messages.
59
58
import logging
60
59
import os
61
60
import sys
62
 
import re
63
61
import time
64
62
 
65
63
from bzrlib.lazy_import import lazy_import
67
65
from cStringIO import StringIO
68
66
import errno
69
67
import locale
 
68
import tempfile
70
69
import traceback
71
70
""")
72
71
 
73
72
import bzrlib
74
73
 
 
74
from bzrlib.symbol_versioning import (
 
75
    deprecated_function,
 
76
    deprecated_in,
 
77
    )
 
78
 
75
79
lazy_import(globals(), """
76
80
from bzrlib import (
77
81
    debug,
78
82
    errors,
79
83
    osutils,
80
 
    plugin,
81
 
    symbol_versioning,
 
84
    ui,
82
85
    )
83
86
""")
84
87
 
107
110
 
108
111
 
109
112
def note(*args, **kwargs):
 
113
    """Output a note to the user.
 
114
 
 
115
    Takes the same parameters as logging.info.
 
116
 
 
117
    :return: None
 
118
    """
110
119
    # FIXME note always emits utf-8, regardless of the terminal encoding
111
120
    #
112
121
    # FIXME: clearing the ui and then going through the abstract logging
113
122
    # framework is whack; we should probably have a logging Handler that
114
123
    # deals with terminal output if needed.
115
 
    import bzrlib.ui
116
 
    bzrlib.ui.ui_factory.clear_term()
 
124
    ui.ui_factory.clear_term()
117
125
    _bzr_logger.info(*args, **kwargs)
118
126
 
119
127
 
120
128
def warning(*args, **kwargs):
121
 
    import bzrlib.ui
122
 
    bzrlib.ui.ui_factory.clear_term()
 
129
    ui.ui_factory.clear_term()
123
130
    _bzr_logger.warning(*args, **kwargs)
124
131
 
125
132
 
126
 
# configure convenient aliases for output routines
127
 
#
128
 
# TODO: deprecate them, have one name for each.
129
 
info = note
130
 
log_error = _bzr_logger.error
131
 
error =     _bzr_logger.error
132
 
 
133
 
 
134
 
_last_mutter_flush_time = None
 
133
@deprecated_function(deprecated_in((2, 1, 0)))
 
134
def info(*args, **kwargs):
 
135
    """Deprecated: use trace.note instead."""
 
136
    note(*args, **kwargs)
 
137
 
 
138
 
 
139
@deprecated_function(deprecated_in((2, 1, 0)))
 
140
def log_error(*args, **kwargs):
 
141
    """Deprecated: use bzrlib.trace.show_error instead"""
 
142
    _bzr_logger.error(*args, **kwargs)
 
143
 
 
144
 
 
145
@deprecated_function(deprecated_in((2, 1, 0)))
 
146
def error(*args, **kwargs):
 
147
    """Deprecated: use bzrlib.trace.show_error instead"""
 
148
    _bzr_logger.error(*args, **kwargs)
 
149
 
 
150
 
 
151
def show_error(*args, **kwargs):
 
152
    """Show an error message to the user.
 
153
 
 
154
    Don't use this for exceptions, use report_exception instead.
 
155
    """
 
156
    _bzr_logger.error(*args, **kwargs)
 
157
 
135
158
 
136
159
def mutter(fmt, *args):
137
 
    global _last_mutter_flush_time
138
160
    if _trace_file is None:
139
161
        return
 
162
    # XXX: Don't check this every time; instead anyone who closes the file
 
163
    # ought to deregister it.  We can tolerate None.
140
164
    if (getattr(_trace_file, 'closed', None) is not None) and _trace_file.closed:
141
165
        return
142
166
 
159
183
    timestamp = '%0.3f  ' % (now - _bzr_log_start_time,)
160
184
    out = timestamp + out + '\n'
161
185
    _trace_file.write(out)
162
 
    # We flush if we haven't flushed for a few seconds. We don't want to flush
163
 
    # on every mutter, but when a command takes a while, it can be nice to see
164
 
    # updates in the debug log.
165
 
    if (_last_mutter_flush_time is None
166
 
        or (now - _last_mutter_flush_time) > 2.0):
167
 
        flush = getattr(_trace_file, 'flush', None)
168
 
        if flush is not None:
169
 
            flush()
170
 
        _last_mutter_flush_time = now
 
186
    # there's no explicit flushing; the file is typically line buffered.
171
187
 
172
188
 
173
189
def mutter_callsite(stacklevel, fmt, *args):
225
241
    This sets the global _bzr_log_filename.
226
242
    """
227
243
    global _bzr_log_filename
 
244
 
 
245
    def _open_or_create_log_file(filename):
 
246
        """Open existing log file, or create with ownership and permissions
 
247
 
 
248
        It inherits the ownership and permissions (masked by umask) from
 
249
        the containing directory to cope better with being run under sudo
 
250
        with $HOME still set to the user's homedir.
 
251
        """
 
252
        flags = os.O_WRONLY | os.O_APPEND | osutils.O_TEXT
 
253
        while True:
 
254
            try:
 
255
                fd = os.open(filename, flags)
 
256
                break
 
257
            except OSError, e:
 
258
                if e.errno != errno.ENOENT:
 
259
                    raise
 
260
            try:
 
261
                fd = os.open(filename, flags | os.O_CREAT | os.O_EXCL, 0666)
 
262
            except OSError, e:
 
263
                if e.errno != errno.EEXIST:
 
264
                    raise
 
265
            else:
 
266
                osutils.copy_ownership_from_path(filename)
 
267
                break
 
268
        return os.fdopen(fd, 'at', 0) # unbuffered
 
269
 
 
270
 
228
271
    _bzr_log_filename = _get_bzr_log_filename()
229
272
    _rollover_trace_maybe(_bzr_log_filename)
230
273
    try:
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
 
274
        bzr_log_file = _open_or_create_log_file(_bzr_log_filename)
233
275
        bzr_log_file.write('\n')
234
276
        if bzr_log_file.tell() <= 2:
235
277
            bzr_log_file.write("this is a debug log for diagnosing/reporting problems in bzr\n")
236
278
            bzr_log_file.write("you can delete or truncate this file, or include sections in\n")
237
279
            bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
 
280
 
238
281
        return bzr_log_file
239
 
    except IOError, e:
240
 
        warning("failed to open trace file: %s" % (e))
 
282
 
 
283
    except EnvironmentError, e:
 
284
        # If we are failing to open the log, then most likely logging has not
 
285
        # been set up yet. So we just write to stderr rather than using
 
286
        # 'warning()'. If we using warning(), users get the unhelpful 'no
 
287
        # handlers registered for "bzr"' when something goes wrong on the
 
288
        # server. (bug #503886)
 
289
        sys.stderr.write("failed to open trace file: %s\n" % (e,))
241
290
    # TODO: What should happen if we fail to open the trace file?  Maybe the
242
291
    # objects should be pointed at /dev/null or the equivalent?  Currently
243
292
    # returns None which will cause failures later.
254
303
    logging.getLogger("bzr").
255
304
 
256
305
    Output can be redirected away by calling _push_log_file.
 
306
 
 
307
    :return: A memento from push_log_file for restoring the log state.
257
308
    """
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
309
    start_time = osutils.format_local_date(_bzr_log_start_time,
262
310
                                           timezone='local')
263
311
    # create encoded wrapper around stderr
264
312
    bzr_log_file = _open_bzr_log()
265
313
    if bzr_log_file is not None:
266
314
        bzr_log_file.write(start_time.encode('utf-8') + '\n')
267
 
    push_log_file(bzr_log_file,
 
315
    memento = push_log_file(bzr_log_file,
268
316
        r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s',
269
317
        r'%Y-%m-%d %H:%M:%S')
270
318
    # after hooking output into bzr_log, we also need to attach a stderr
271
319
    # handler, writing only at level info and with encoding
 
320
    term_encoding = osutils.get_terminal_encoding()
272
321
    writer_factory = codecs.getwriter(term_encoding)
273
322
    encoded_stderr = writer_factory(sys.stderr, errors='replace')
274
323
    stderr_handler = logging.StreamHandler(encoded_stderr)
275
324
    stderr_handler.setLevel(logging.INFO)
276
325
    logging.getLogger('bzr').addHandler(stderr_handler)
 
326
    return memento
277
327
 
278
328
 
279
329
def push_log_file(to_file, log_format=None, date_format=None):
282
332
    :param to_file: A file-like object to which messages will be sent.
283
333
 
284
334
    :returns: A memento that should be passed to _pop_log_file to restore the
285
 
    previously active logging.
 
335
        previously active logging.
286
336
    """
287
337
    global _trace_file
288
338
    # make a new handler
315
365
def pop_log_file((magic, old_handlers, new_handler, old_trace_file, new_trace_file)):
316
366
    """Undo changes to logging/tracing done by _push_log_file.
317
367
 
318
 
    This flushes, but does not close the trace file.
 
368
    This flushes, but does not close the trace file (so that anything that was
 
369
    in it is output.
319
370
 
320
371
    Takes the memento returned from _push_log_file."""
321
372
    global _trace_file
322
373
    _trace_file = old_trace_file
323
374
    bzr_logger = logging.getLogger('bzr')
324
375
    bzr_logger.removeHandler(new_handler)
325
 
    # must be closed, otherwise logging will try to close it atexit, and the
 
376
    # must be closed, otherwise logging will try to close it at exit, and the
326
377
    # file will likely already be closed underneath.
327
378
    new_handler.close()
328
379
    bzr_logger.handlers = old_handlers
329
 
    new_trace_file.flush()
 
380
    if new_trace_file is not None:
 
381
        new_trace_file.flush()
330
382
 
331
383
 
332
384
def log_exception_quietly():
347
399
    global _verbosity_level
348
400
    _verbosity_level = level
349
401
    _update_logging_level(level < 0)
 
402
    ui.ui_factory.be_quiet(level < 0)
350
403
 
351
404
 
352
405
def get_verbosity_level():
358
411
 
359
412
 
360
413
def be_quiet(quiet=True):
361
 
    # Perhaps this could be deprecated now ...
362
414
    if quiet:
363
415
        set_verbosity_level(-1)
364
416
    else:
414
466
                    note(line)
415
467
                    break
416
468
 
 
469
def _dump_memory_usage(err_file):
 
470
    try:
 
471
        try:
 
472
            fd, name = tempfile.mkstemp(prefix="bzr_memdump", suffix=".json")
 
473
            dump_file = os.fdopen(fd, 'w')
 
474
            from meliae import scanner
 
475
            scanner.dump_gc_objects(dump_file)
 
476
            err_file.write("Memory dumped to %s\n" % name)
 
477
        except ImportError:
 
478
            err_file.write("Dumping memory requires meliae module.\n")
 
479
            log_exception_quietly()
 
480
        except:
 
481
            err_file.write("Exception while dumping memory.\n")
 
482
            log_exception_quietly()
 
483
    finally:
 
484
        if dump_file is not None:
 
485
            dump_file.close()
 
486
        elif fd is not None:
 
487
            os.close(fd)
 
488
 
 
489
 
 
490
def _qualified_exception_name(eclass, unqualified_bzrlib_errors=False):
 
491
    """Give name of error class including module for non-builtin exceptions
 
492
 
 
493
    If `unqualified_bzrlib_errors` is True, errors specific to bzrlib will
 
494
    also omit the module prefix.
 
495
    """
 
496
    class_name = eclass.__name__
 
497
    module_name = eclass.__module__
 
498
    if module_name in ("exceptions", "__main__") or (
 
499
            unqualified_bzrlib_errors and module_name == "bzrlib.errors"):
 
500
        return class_name
 
501
    return "%s.%s" % (module_name, class_name)
 
502
 
417
503
 
418
504
def report_exception(exc_info, err_file):
419
505
    """Report an exception to err_file (typically stderr) and to .bzr.log.
422
508
 
423
509
    :return: The appropriate exit code for this error.
424
510
    """
425
 
    exc_type, exc_object, exc_tb = exc_info
426
511
    # Log the full traceback to ~/.bzr.log
427
512
    log_exception_quietly()
 
513
    if 'error' in debug.debug_flags:
 
514
        print_exception(exc_info, err_file)
 
515
        return errors.EXIT_ERROR
 
516
    exc_type, exc_object, exc_tb = exc_info
428
517
    if (isinstance(exc_object, IOError)
429
518
        and getattr(exc_object, 'errno', None) == errno.EPIPE):
430
519
        err_file.write("bzr: broken pipe\n")
432
521
    elif isinstance(exc_object, KeyboardInterrupt):
433
522
        err_file.write("bzr: interrupted\n")
434
523
        return errors.EXIT_ERROR
 
524
    elif isinstance(exc_object, MemoryError):
 
525
        err_file.write("bzr: out of memory\n")
 
526
        if 'mem_dump' in debug.debug_flags:
 
527
            _dump_memory_usage(err_file)
 
528
        else:
 
529
            err_file.write("Use -Dmem_dump to dump memory to a file.\n")
 
530
        return errors.EXIT_ERROR
435
531
    elif isinstance(exc_object, ImportError) \
436
532
        and str(exc_object).startswith("No module named "):
437
533
        report_user_error(exc_info, err_file,
440
536
    elif not getattr(exc_object, 'internal_error', True):
441
537
        report_user_error(exc_info, err_file)
442
538
        return errors.EXIT_ERROR
443
 
    elif isinstance(exc_object, (OSError, IOError)):
 
539
    elif isinstance(exc_object, (OSError, IOError)) or (
 
540
        # GZ 2010-05-20: Like (exc_type is pywintypes.error) but avoid import
 
541
        exc_type.__name__ == "error" and exc_type.__module__ == "pywintypes"):
444
542
        # Might be nice to catch all of these and show them as something more
445
543
        # specific, but there are too many cases at the moment.
446
544
        report_user_error(exc_info, err_file)
468
566
    :param advice: Extra advice to the user to be printed following the
469
567
        exception.
470
568
    """
471
 
    if 'error' in debug.debug_flags:
472
 
        print_exception(exc_info, err_file)
473
 
        return
474
569
    err_file.write("bzr: ERROR: %s\n" % (exc_info[1],))
475
570
    if advice:
476
571
        err_file.write("%s\n" % (advice,))
478
573
 
479
574
def report_bug(exc_info, err_file):
480
575
    """Report an exception that probably indicates a bug in bzr"""
481
 
    print_exception(exc_info, err_file)
482
 
    err_file.write('\n')
483
 
    err_file.write('bzr %s on python %s (%s)\n' % \
484
 
                       (bzrlib.__version__,
485
 
                        bzrlib._format_version_tuple(sys.version_info),
486
 
                        sys.platform))
487
 
    err_file.write('arguments: %r\n' % sys.argv)
488
 
    err_file.write(
489
 
        'encoding: %r, fsenc: %r, lang: %r\n' % (
490
 
            osutils.get_user_encoding(), sys.getfilesystemencoding(),
491
 
            os.environ.get('LANG')))
492
 
    err_file.write("plugins:\n")
493
 
    for name, a_plugin in sorted(plugin.plugins().items()):
494
 
        err_file.write("  %-20s %s [%s]\n" %
495
 
            (name, a_plugin.path(), a_plugin.__version__))
496
 
    err_file.write(
497
 
"""\
498
 
*** Bazaar has encountered an internal error.
499
 
    Please report a bug at https://bugs.launchpad.net/bzr/+filebug
500
 
    including this traceback, and a description of what you
501
 
    were doing when the error occurred.
502
 
""")
 
576
    from bzrlib.crash import report_bug
 
577
    report_bug(exc_info, err_file)
 
578
 
 
579
 
 
580
def _flush_stdout_stderr():
 
581
    # called from the bzrlib library finalizer returned by bzrlib.initialize()
 
582
    try:
 
583
        sys.stdout.flush()
 
584
        sys.stderr.flush()
 
585
    except IOError, e:
 
586
        import errno
 
587
        if e.errno in [errno.EINVAL, errno.EPIPE]:
 
588
            pass
 
589
        else:
 
590
            raise
 
591
 
 
592
 
 
593
def _flush_trace():
 
594
    # called from the bzrlib library finalizer returned by bzrlib.initialize()
 
595
    global _trace_file
 
596
    if _trace_file:
 
597
        _trace_file.flush()
 
598
 
 
599
 
 
600
class Config(object):
 
601
    """Configuration of message tracing in bzrlib.
 
602
 
 
603
    This implements the context manager protocol and should manage any global
 
604
    variables still used. The default config used is DefaultConfig, but
 
605
    embedded uses of bzrlib may wish to use a custom manager.
 
606
    """
 
607
 
 
608
    def __enter__(self):
 
609
        return self # This is bound to the 'as' clause in a with statement.
 
610
 
 
611
    def __exit__(self, exc_type, exc_val, exc_tb):
 
612
        return False # propogate exceptions.
 
613
 
 
614
 
 
615
class DefaultConfig(Config):
 
616
    """A default configuration for tracing of messages in bzrlib.
 
617
 
 
618
    This implements the context manager protocol.
 
619
    """
 
620
 
 
621
    def __enter__(self):
 
622
        self._original_filename = _bzr_log_filename
 
623
        self._original_state = enable_default_logging()
 
624
        return self # This is bound to the 'as' clause in a with statement.
 
625
 
 
626
    def __exit__(self, exc_type, exc_val, exc_tb):
 
627
        pop_log_file(self._original_state)
 
628
        global _bzr_log_filename
 
629
        _bzr_log_filename = self._original_filename
 
630
        return False # propogate exceptions.