/brz/remove-bazaar

To get this branch, use:
bzr branch http://gegoxaren.bato24.eu/bzr/brz/remove-bazaar

« back to all changes in this revision

Viewing changes to breezy/tests/test_trace.py

  • Committer: Vincent Ladeuil
  • Date: 2019-11-19 18:10:28 UTC
  • mfrom: (7290.1.43 work)
  • mto: This revision was merged to the branch mainline in revision 7414.
  • Revision ID: v.ladeuil+brz@free.fr-20191119181028-rgajksejntz3vwil
Merge lp:brz/3.0

Show diffs side-by-side

added added

removed removed

Lines of Context:
breezy/tests/test_trace.py
 
1
# Copyright (C) 2005-2011, 2016 Canonical Ltd
 
2
#
 
3
# This program is free software; you can redistribute it and/or modify
 
4
# it under the terms of the GNU General Public License as published by
 
5
# the Free Software Foundation; either version 2 of the License, or
 
6
# (at your option) any later version.
 
7
#
 
8
# This program is distributed in the hope that it will be useful,
 
9
# but WITHOUT ANY WARRANTY; without even the implied warranty of
 
10
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 
11
# GNU General Public License for more details.
 
12
#
 
13
# You should have received a copy of the GNU General Public License
 
14
# along with this program; if not, write to the Free Software
 
15
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
 
16
 
 
17
# "weren't nothing promised to you.  do i look like i got a promise face?"
 
18
 
 
19
"""Tests for trace library"""
 
20
 
 
21
import errno
 
22
import logging
 
23
import os
 
24
import re
 
25
import sys
 
26
import tempfile
 
27
 
 
28
from .. import (
 
29
    debug,
 
30
    errors,
 
31
    trace,
 
32
    )
 
33
from ..sixish import (
 
34
    PY3,
 
35
    StringIO,
 
36
    )
 
37
from . import features, TestCaseInTempDir, TestCase
 
38
from ..trace import (
 
39
    mutter, mutter_callsite, report_exception,
 
40
    set_verbosity_level, get_verbosity_level, is_quiet, is_verbose, be_quiet,
 
41
    pop_log_file,
 
42
    push_log_file,
 
43
    _rollover_trace_maybe,
 
44
    show_error,
 
45
    )
 
46
 
 
47
 
 
48
def _format_exception():
 
49
    """Format an exception as it would normally be displayed to the user"""
 
50
    buf = StringIO()
 
51
    report_exception(sys.exc_info(), buf)
 
52
    return buf.getvalue()
 
53
 
 
54
 
 
55
class TestTrace(TestCase):
 
56
 
 
57
    def test_format_sys_exception(self):
 
58
        # Test handling of an internal/unexpected error that probably
 
59
        # indicates a bug in brz.  The details of the message may vary
 
60
        # depending on whether apport is available or not.  See test_crash for
 
61
        # more.
 
62
        try:
 
63
            raise NotImplementedError("time travel")
 
64
        except NotImplementedError:
 
65
            err = _format_exception()
 
66
        self.assertContainsRe(err,
 
67
                              '^brz: ERROR: NotImplementedError: time travel')
 
68
        self.assertContainsRe(err,
 
69
                              'Bazaar has encountered an internal error.')
 
70
 
 
71
    def test_format_interrupt_exception(self):
 
72
        try:
 
73
            raise KeyboardInterrupt()
 
74
        except KeyboardInterrupt:
 
75
            # XXX: Some risk that a *real* keyboard interrupt won't be seen
 
76
            msg = _format_exception()
 
77
        self.assertEqual(msg, 'brz: interrupted\n')
 
78
 
 
79
    def test_format_memory_error(self):
 
80
        try:
 
81
            raise MemoryError()
 
82
        except MemoryError:
 
83
            msg = _format_exception()
 
84
        self.assertEqual(
 
85
            msg,
 
86
            "brz: out of memory\nUse -Dmem_dump to dump memory to a file.\n")
 
87
 
 
88
    def test_format_mem_dump(self):
 
89
        self.requireFeature(features.meliae)
 
90
        debug.debug_flags.add('mem_dump')
 
91
        try:
 
92
            raise MemoryError()
 
93
        except MemoryError:
 
94
            msg = _format_exception()
 
95
        self.assertStartsWith(msg,
 
96
                              "brz: out of memory\nMemory dumped to ")
 
97
 
 
98
    def test_format_os_error(self):
 
99
        try:
 
100
            os.rmdir('nosuchfile22222')
 
101
        except OSError as e:
 
102
            e_str = str(e)
 
103
            msg = _format_exception()
 
104
        # Linux seems to give "No such file" but Windows gives "The system
 
105
        # cannot find the file specified".
 
106
        self.assertEqual('brz: ERROR: %s\n' % (e_str,), msg)
 
107
 
 
108
    def test_format_io_error(self):
 
109
        try:
 
110
            open('nosuchfile22222')
 
111
        except IOError:
 
112
            msg = _format_exception()
 
113
        # Even though Windows and Linux differ for 'os.rmdir', they both give
 
114
        # 'No such file' for open()
 
115
        # However it now gets translated so we can not test for a specific
 
116
        # message
 
117
        self.assertContainsRe(msg,
 
118
                              '^brz: ERROR: \\[Errno .*\\] .*nosuchfile')
 
119
 
 
120
    def test_format_pywintypes_error(self):
 
121
        self.requireFeature(features.pywintypes)
 
122
        import pywintypes
 
123
        import win32file
 
124
        try:
 
125
            win32file.RemoveDirectory('nosuchfile22222')
 
126
        except pywintypes.error:
 
127
            msg = _format_exception()
 
128
        # GZ 2010-05-03: Formatting for pywintypes.error is basic, a 3-tuple
 
129
        #                with errno, function name, and locale error message
 
130
        self.assertContainsRe(
 
131
            msg, "^brz: ERROR: \\(2, 'RemoveDirectory[AW]?', .*\\)")
 
132
 
 
133
    def test_format_sockets_error(self):
 
134
        try:
 
135
            import socket
 
136
            sock = socket.socket()
 
137
            sock.send(b"This should fail.")
 
138
        except socket.error:
 
139
            msg = _format_exception()
 
140
 
 
141
        self.assertNotContainsRe(msg,
 
142
                                 "Traceback \\(most recent call last\\):")
 
143
 
 
144
    def test_format_unicode_error(self):
 
145
        try:
 
146
            raise errors.BzrCommandError(u'argument foo\xb5 does not exist')
 
147
        except errors.BzrCommandError:
 
148
            msg = _format_exception()
 
149
        if PY3:
 
150
            expected = 'brz: ERROR: argument foo\xb5 does not exist\n'
 
151
        else:
 
152
            # GZ 2017-06-10: Pretty bogus, should encode per the output stream
 
153
            expected = 'brz: ERROR: argument foo\xc2\xb5 does not exist\n'
 
154
        self.assertEqual(msg, expected)
 
155
 
 
156
    def test_format_exception(self):
 
157
        """Short formatting of brz exceptions"""
 
158
        try:
 
159
            raise errors.NotBranchError('wibble')
 
160
        except errors.NotBranchError:
 
161
            msg = _format_exception()
 
162
        self.assertEqual(msg, 'brz: ERROR: Not a branch: \"wibble\".\n')
 
163
 
 
164
    def test_report_external_import_error(self):
 
165
        """Short friendly message for missing system modules."""
 
166
        try:
 
167
            import ImaginaryModule
 
168
        except ImportError:
 
169
            msg = _format_exception()
 
170
        else:
 
171
            self.fail("somehow succeeded in importing %r" % ImaginaryModule)
 
172
        self.assertContainsRe(
 
173
            msg,
 
174
            "^brz: ERROR: No module named '?ImaginaryModule'?\n"
 
175
            "You may need to install this Python library separately.\n$")
 
176
 
 
177
    def test_report_import_syntax_error(self):
 
178
        try:
 
179
            raise ImportError("syntax error")
 
180
        except ImportError:
 
181
            msg = _format_exception()
 
182
        self.assertContainsRe(msg,
 
183
                              'Bazaar has encountered an internal error')
 
184
 
 
185
    def test_trace_unicode(self):
 
186
        """Write Unicode to trace log"""
 
187
        self.log(u'the unicode character for benzene is \N{BENZENE RING}')
 
188
        log = self.get_log()
 
189
        self.assertContainsRe(log, "the unicode character for benzene is")
 
190
 
 
191
    def test_trace_argument_unicode(self):
 
192
        """Write a Unicode argument to the trace log"""
 
193
        mutter(u'the unicode character for benzene is %s', u'\N{BENZENE RING}')
 
194
        log = self.get_log()
 
195
        self.assertContainsRe(log, 'the unicode character')
 
196
 
 
197
    def test_trace_argument_utf8(self):
 
198
        """Write a Unicode argument to the trace log"""
 
199
        mutter(u'the unicode character for benzene is %s',
 
200
               u'\N{BENZENE RING}'.encode('utf-8'))
 
201
        log = self.get_log()
 
202
        self.assertContainsRe(log, 'the unicode character')
 
203
 
 
204
    def test_trace_argument_exception(self):
 
205
        err = Exception('an error')
 
206
        mutter(u'can format stringable classes %s', err)
 
207
        log = self.get_log()
 
208
        self.assertContainsRe(log, 'can format stringable classes an error')
 
209
 
 
210
    def test_report_broken_pipe(self):
 
211
        try:
 
212
            raise IOError(errno.EPIPE, 'broken pipe foofofo')
 
213
        except IOError:
 
214
            msg = _format_exception()
 
215
            self.assertEqual(msg, "brz: broken pipe\n")
 
216
        else:
 
217
            self.fail("expected error not raised")
 
218
 
 
219
    def assertLogContainsLine(self, log, string):
 
220
        """Assert log contains a line including log timestamp."""
 
221
        # Does not check absolute position in log as there may be kipple.
 
222
        self.assertContainsRe(log,
 
223
                              '(?m)^\\d+\\.\\d+  ' + re.escape(string))
 
224
 
 
225
    def test_mutter_callsite_1(self):
 
226
        """mutter_callsite can capture 1 level of stack frame."""
 
227
        mutter_callsite(1, "foo %s", "a string")
 
228
        log = self.get_log()
 
229
        # begin with the message
 
230
        self.assertLogContainsLine(log, 'foo a string\nCalled from:\n')
 
231
        # should show two frame: this frame and the one above
 
232
        self.assertContainsRe(
 
233
            log, 'test_trace\\.py", line \\d+, in test_mutter_callsite_1\n')
 
234
        # this frame should be the final one
 
235
        self.assertEndsWith(log, ' "a string")\n')
 
236
 
 
237
    def test_mutter_callsite_2(self):
 
238
        """mutter_callsite can capture 2 levels of stack frame."""
 
239
        mutter_callsite(2, "foo %s", "a string")
 
240
        log = self.get_log()
 
241
        # begin with the message
 
242
        self.assertLogContainsLine(log, 'foo a string\nCalled from:\n')
 
243
        # should show two frame: this frame and the one above
 
244
        self.assertContainsRe(
 
245
            log, 'test_trace.py", line \\d+, in test_mutter_callsite_2\n')
 
246
        # this frame should be the final one
 
247
        self.assertEndsWith(log, ' "a string")\n')
 
248
 
 
249
    def test_mutter_never_fails(self):
 
250
        """Even with unencodable input mutter should not raise errors."""
 
251
        mutter(u'can write unicode \xa7')
 
252
        mutter('can interpolate unicode %s', u'\xa7')
 
253
        mutter(b'can write bytes \xa7')
 
254
        mutter('can repr bytes %r', b'\xa7')
 
255
        mutter('can interpolate bytes %s', b'\xa7')
 
256
        # Log will always be written as utf-8
 
257
        log = self.get_log()
 
258
        self.assertContainsRe(
 
259
            log,
 
260
            u'.* +can write unicode \xa7\n'
 
261
            u'.* +can interpolate unicode \xa7\n'
 
262
            u'.* +can write bytes \ufffd\n'
 
263
            u'.* +can repr bytes b\'\\\\xa7\'\n'
 
264
            u'.* +can interpolate bytes (?:\ufffd|b\'\\\\xa7\')\n')
 
265
 
 
266
    def test_show_error(self):
 
267
        show_error('error1')
 
268
        show_error(u'error2 \xb5 blah')
 
269
        show_error('arg: %s', 'blah')
 
270
        show_error('arg2: %(key)s', {'key': 'stuff'})
 
271
        try:
 
272
            raise Exception("oops")
 
273
        except BaseException:
 
274
            show_error('kwarg', exc_info=True)
 
275
        log = self.get_log()
 
276
        self.assertContainsRe(log, 'error1')
 
277
        self.assertContainsRe(log, u'error2 \xb5 blah')
 
278
        self.assertContainsRe(log, 'arg: blah')
 
279
        self.assertContainsRe(log, 'arg2: stuff')
 
280
        self.assertContainsRe(log, 'kwarg')
 
281
        self.assertContainsRe(log, 'Traceback \\(most recent call last\\):')
 
282
        self.assertContainsRe(
 
283
            log, 'File ".*test_trace.py", line .*, in test_show_error')
 
284
        self.assertContainsRe(log, 'raise Exception\\("oops"\\)')
 
285
        self.assertContainsRe(log, 'Exception: oops')
 
286
 
 
287
    def test_push_log_file(self):
 
288
        """Can push and pop log file, and this catches mutter messages.
 
289
 
 
290
        This is primarily for use in the test framework.
 
291
        """
 
292
        tmp1 = tempfile.NamedTemporaryFile()
 
293
        tmp2 = tempfile.NamedTemporaryFile()
 
294
        try:
 
295
            memento1 = push_log_file(tmp1)
 
296
            mutter("comment to file1")
 
297
            try:
 
298
                memento2 = push_log_file(tmp2)
 
299
                try:
 
300
                    mutter("comment to file2")
 
301
                finally:
 
302
                    pop_log_file(memento2)
 
303
                mutter("again to file1")
 
304
            finally:
 
305
                pop_log_file(memento1)
 
306
            # the files were opened in binary mode, so should have exactly
 
307
            # these bytes.  and removing the file as the log target should
 
308
            # have caused them to be flushed out.  need to match using regexps
 
309
            # as there's a timestamp at the front.
 
310
            tmp1.seek(0)
 
311
            self.assertContainsRe(tmp1.read(),
 
312
                                  b"\\d+\\.\\d+  comment to file1\n"
 
313
                                  b"\\d+\\.\\d+  again to file1\n")
 
314
            tmp2.seek(0)
 
315
            self.assertContainsRe(tmp2.read(),
 
316
                                  b"\\d+\\.\\d+  comment to file2\n")
 
317
        finally:
 
318
            tmp1.close()
 
319
            tmp2.close()
 
320
 
 
321
    def test__open_brz_log_uses_stderr_for_failures(self):
 
322
        # If _open_brz_log cannot open the file, then we should write the
 
323
        # warning to stderr. Since this is normally happening before logging is
 
324
        # set up.
 
325
        self.overrideAttr(sys, 'stderr', StringIO())
 
326
        # Set the log file to something that cannot exist
 
327
        self.overrideEnv('BRZ_LOG', '/no-such-dir/brz.log')
 
328
        self.overrideAttr(trace, '_brz_log_filename')
 
329
        logf = trace._open_brz_log()
 
330
        self.assertIs(None, logf)
 
331
        self.assertContainsRe(
 
332
            sys.stderr.getvalue(),
 
333
            "failed to open trace file: .* '/no-such-dir/brz.log'$")
 
334
 
 
335
    def test__open_brz_log_ignores_cache_dir_error(self):
 
336
        # If the cache directory can not be created and _open_brz_log can thus
 
337
        # not open the file, then we should write the warning to stderr. Since
 
338
        # this is normally happening before logging is set up.
 
339
        self.overrideAttr(sys, 'stderr', StringIO())
 
340
        # Set the cache directory to something that cannot exist
 
341
        self.overrideEnv('BRZ_LOG', None)
 
342
        self.overrideEnv('BRZ_HOME', '/no-such-dir')
 
343
        self.overrideEnv('XDG_CACHE_HOME', '/no-such-dir')
 
344
        self.overrideAttr(trace, '_brz_log_filename')
 
345
        logf = trace._open_brz_log()
 
346
        self.assertIs(None, logf)
 
347
        self.assertContainsRe(
 
348
            sys.stderr.getvalue(),
 
349
            "failed to open trace file: .* '/no-such-dir'$")
 
350
 
 
351
 
 
352
class TestVerbosityLevel(TestCase):
 
353
 
 
354
    def test_verbosity_level(self):
 
355
        set_verbosity_level(1)
 
356
        self.assertEqual(1, get_verbosity_level())
 
357
        self.assertTrue(is_verbose())
 
358
        self.assertFalse(is_quiet())
 
359
        set_verbosity_level(-1)
 
360
        self.assertEqual(-1, get_verbosity_level())
 
361
        self.assertFalse(is_verbose())
 
362
        self.assertTrue(is_quiet())
 
363
        set_verbosity_level(0)
 
364
        self.assertEqual(0, get_verbosity_level())
 
365
        self.assertFalse(is_verbose())
 
366
        self.assertFalse(is_quiet())
 
367
 
 
368
    def test_be_quiet(self):
 
369
        # Confirm the old API still works
 
370
        be_quiet(True)
 
371
        self.assertEqual(-1, get_verbosity_level())
 
372
        be_quiet(False)
 
373
        self.assertEqual(0, get_verbosity_level())
 
374
 
 
375
 
 
376
class TestLogging(TestCase):
 
377
    """Check logging functionality robustly records information"""
 
378
 
 
379
    def test_note(self):
 
380
        trace.note("Noted")
 
381
        self.assertEqual("    INFO  Noted\n", self.get_log())
 
382
 
 
383
    def test_warning(self):
 
384
        trace.warning("Warned")
 
385
        self.assertEqual(" WARNING  Warned\n", self.get_log())
 
386
 
 
387
    def test_log(self):
 
388
        logging.getLogger("brz").error("Errored")
 
389
        self.assertEqual("   ERROR  Errored\n", self.get_log())
 
390
 
 
391
    def test_log_sub(self):
 
392
        logging.getLogger("brz.test_log_sub").debug("Whispered")
 
393
        self.assertEqual("   DEBUG  Whispered\n", self.get_log())
 
394
 
 
395
    def test_log_unicode_msg(self):
 
396
        logging.getLogger("brz").debug(u"\xa7")
 
397
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
398
 
 
399
    def test_log_unicode_arg(self):
 
400
        logging.getLogger("brz").debug("%s", u"\xa7")
 
401
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
402
 
 
403
    def test_log_utf8_msg(self):
 
404
        logging.getLogger("brz").debug(b"\xc2\xa7")
 
405
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
406
 
 
407
    def test_log_utf8_arg(self):
 
408
        logging.getLogger("brz").debug(b"%s", b"\xc2\xa7")
 
409
        if PY3:
 
410
            expected = u"   DEBUG  b'\\xc2\\xa7'\n"
 
411
        else:
 
412
            expected = u"   DEBUG  \xa7\n"
 
413
        self.assertEqual(expected, self.get_log())
 
414
 
 
415
    def test_log_bytes_msg(self):
 
416
        logging.getLogger("brz").debug(b"\xa7")
 
417
        log = self.get_log()
 
418
        self.assertContainsString(log, "UnicodeDecodeError: ")
 
419
        self.assertContainsRe(
 
420
            log, "Logging record unformattable: b?'\\\\xa7' % \\(\\)\n")
 
421
 
 
422
    def test_log_bytes_arg(self):
 
423
        logging.getLogger("brz").debug(b"%s", b"\xa7")
 
424
        log = self.get_log()
 
425
        if PY3:
 
426
            self.assertEqual(u"   DEBUG  b'\\xa7'\n", self.get_log())
 
427
        else:
 
428
            self.assertContainsString(log, "UnicodeDecodeError: ")
 
429
            self.assertContainsRe(
 
430
                log,
 
431
                "Logging record unformattable: ?'%s' % \\(b?'\\\\xa7',\\)\n")
 
432
 
 
433
    def test_log_mixed_strings(self):
 
434
        logging.getLogger("brz").debug(u"%s", b"\xa7")
 
435
        log = self.get_log()
 
436
        if PY3:
 
437
            self.assertEqual(u"   DEBUG  b'\\xa7'\n", self.get_log())
 
438
        else:
 
439
            self.assertContainsString(log, "UnicodeDecodeError: ")
 
440
            self.assertContainsRe(
 
441
                log,
 
442
                "Logging record unformattable: u'%s' % \\('\\\\xa7',\\)\n")
 
443
 
 
444
    def test_log_repr_broken(self):
 
445
        class BadRepr(object):
 
446
            def __repr__(self):
 
447
                raise ValueError("Broken object")
 
448
        logging.getLogger("brz").debug("%s", BadRepr())
 
449
        log = self.get_log()
 
450
        self.assertContainsRe(log, "ValueError: Broken object\n")
 
451
        self.assertContainsRe(log, "Logging record unformattable: '%s' % .*\n")
 
452
 
 
453
 
 
454
class TestBzrLog(TestCaseInTempDir):
 
455
 
 
456
    def test_log_rollover(self):
 
457
        temp_log_name = 'test-log'
 
458
        trace_file = open(temp_log_name, 'at')
 
459
        trace_file.writelines(['test_log_rollover padding\n'] * 200000)
 
460
        trace_file.close()
 
461
        _rollover_trace_maybe(temp_log_name)
 
462
        # should have been rolled over
 
463
        self.assertFalse(os.access(temp_log_name, os.R_OK))
 
464
 
 
465
 
 
466
class TestTraceConfiguration(TestCaseInTempDir):
 
467
 
 
468
    def test_default_config(self):
 
469
        config = trace.DefaultConfig()
 
470
        self.overrideAttr(trace, "_brz_log_filename", None)
 
471
        trace._brz_log_filename = None
 
472
        expected_filename = trace._get_brz_log_filename()
 
473
        self.assertEqual(None, trace._brz_log_filename)
 
474
        config.__enter__()
 
475
        try:
 
476
            # Should have entered and setup a default filename.
 
477
            self.assertEqual(expected_filename, trace._brz_log_filename)
 
478
        finally:
 
479
            config.__exit__(None, None, None)
 
480
            # Should have exited and cleaned up.
 
481
            self.assertEqual(None, trace._brz_log_filename)