/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: Jelmer Vernooij
  • Date: 2020-04-05 19:11:34 UTC
  • mto: (7490.7.16 work)
  • mto: This revision was merged to the branch mainline in revision 7501.
  • Revision ID: jelmer@jelmer.uk-20200405191134-0aebh8ikiwygxma5
Populate the .gitignore file.

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, TestSkipped
 
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
        if os.path.isdir('/no-such-dir'):
 
331
            raise TestSkipped('directory creation succeeded')
 
332
        self.assertIs(None, logf)
 
333
        self.assertContainsRe(
 
334
            sys.stderr.getvalue(),
 
335
            "failed to open trace file: .* '/no-such-dir/brz.log'$")
 
336
 
 
337
    def test__open_brz_log_ignores_cache_dir_error(self):
 
338
        # If the cache directory can not be created and _open_brz_log can thus
 
339
        # not open the file, then we should write the warning to stderr. Since
 
340
        # this is normally happening before logging is set up.
 
341
        self.overrideAttr(sys, 'stderr', StringIO())
 
342
        # Set the cache directory to something that cannot exist
 
343
        self.overrideEnv('BRZ_LOG', None)
 
344
        self.overrideEnv('BRZ_HOME', '/no-such-dir')
 
345
        self.overrideEnv('XDG_CACHE_HOME', '/no-such-dir')
 
346
        self.overrideAttr(trace, '_brz_log_filename')
 
347
        logf = trace._open_brz_log()
 
348
        if os.path.isdir('/no-such-dir'):
 
349
            raise TestSkipped('directory creation succeeded')
 
350
        self.assertIs(None, logf)
 
351
        self.assertContainsRe(
 
352
            sys.stderr.getvalue(),
 
353
            "failed to open trace file: .* '/no-such-dir'$")
 
354
 
 
355
 
 
356
class TestVerbosityLevel(TestCase):
 
357
 
 
358
    def test_verbosity_level(self):
 
359
        set_verbosity_level(1)
 
360
        self.assertEqual(1, get_verbosity_level())
 
361
        self.assertTrue(is_verbose())
 
362
        self.assertFalse(is_quiet())
 
363
        set_verbosity_level(-1)
 
364
        self.assertEqual(-1, get_verbosity_level())
 
365
        self.assertFalse(is_verbose())
 
366
        self.assertTrue(is_quiet())
 
367
        set_verbosity_level(0)
 
368
        self.assertEqual(0, get_verbosity_level())
 
369
        self.assertFalse(is_verbose())
 
370
        self.assertFalse(is_quiet())
 
371
 
 
372
    def test_be_quiet(self):
 
373
        # Confirm the old API still works
 
374
        be_quiet(True)
 
375
        self.assertEqual(-1, get_verbosity_level())
 
376
        be_quiet(False)
 
377
        self.assertEqual(0, get_verbosity_level())
 
378
 
 
379
 
 
380
class TestLogging(TestCase):
 
381
    """Check logging functionality robustly records information"""
 
382
 
 
383
    def test_note(self):
 
384
        trace.note("Noted")
 
385
        self.assertEqual("    INFO  Noted\n", self.get_log())
 
386
 
 
387
    def test_warning(self):
 
388
        trace.warning("Warned")
 
389
        self.assertEqual(" WARNING  Warned\n", self.get_log())
 
390
 
 
391
    def test_log(self):
 
392
        logging.getLogger("brz").error("Errored")
 
393
        self.assertEqual("   ERROR  Errored\n", self.get_log())
 
394
 
 
395
    def test_log_sub(self):
 
396
        logging.getLogger("brz.test_log_sub").debug("Whispered")
 
397
        self.assertEqual("   DEBUG  Whispered\n", self.get_log())
 
398
 
 
399
    def test_log_unicode_msg(self):
 
400
        logging.getLogger("brz").debug(u"\xa7")
 
401
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
402
 
 
403
    def test_log_unicode_arg(self):
 
404
        logging.getLogger("brz").debug("%s", u"\xa7")
 
405
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
406
 
 
407
    def test_log_utf8_msg(self):
 
408
        logging.getLogger("brz").debug(b"\xc2\xa7")
 
409
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
410
 
 
411
    def test_log_utf8_arg(self):
 
412
        logging.getLogger("brz").debug(b"%s", b"\xc2\xa7")
 
413
        if PY3:
 
414
            expected = u"   DEBUG  b'\\xc2\\xa7'\n"
 
415
        else:
 
416
            expected = u"   DEBUG  \xa7\n"
 
417
        self.assertEqual(expected, self.get_log())
 
418
 
 
419
    def test_log_bytes_msg(self):
 
420
        logging.getLogger("brz").debug(b"\xa7")
 
421
        log = self.get_log()
 
422
        self.assertContainsString(log, "UnicodeDecodeError: ")
 
423
        self.assertContainsRe(
 
424
            log, "Logging record unformattable: b?'\\\\xa7' % \\(\\)\n")
 
425
 
 
426
    def test_log_bytes_arg(self):
 
427
        logging.getLogger("brz").debug(b"%s", b"\xa7")
 
428
        log = self.get_log()
 
429
        if PY3:
 
430
            self.assertEqual(u"   DEBUG  b'\\xa7'\n", self.get_log())
 
431
        else:
 
432
            self.assertContainsString(log, "UnicodeDecodeError: ")
 
433
            self.assertContainsRe(
 
434
                log,
 
435
                "Logging record unformattable: ?'%s' % \\(b?'\\\\xa7',\\)\n")
 
436
 
 
437
    def test_log_mixed_strings(self):
 
438
        logging.getLogger("brz").debug(u"%s", b"\xa7")
 
439
        log = self.get_log()
 
440
        if PY3:
 
441
            self.assertEqual(u"   DEBUG  b'\\xa7'\n", self.get_log())
 
442
        else:
 
443
            self.assertContainsString(log, "UnicodeDecodeError: ")
 
444
            self.assertContainsRe(
 
445
                log,
 
446
                "Logging record unformattable: u'%s' % \\('\\\\xa7',\\)\n")
 
447
 
 
448
    def test_log_repr_broken(self):
 
449
        class BadRepr(object):
 
450
            def __repr__(self):
 
451
                raise ValueError("Broken object")
 
452
        logging.getLogger("brz").debug("%s", BadRepr())
 
453
        log = self.get_log()
 
454
        self.assertContainsRe(log, "ValueError: Broken object\n")
 
455
        self.assertContainsRe(log, "Logging record unformattable: '%s' % .*\n")
 
456
 
 
457
 
 
458
class TestBzrLog(TestCaseInTempDir):
 
459
 
 
460
    def test_log_rollover(self):
 
461
        temp_log_name = 'test-log'
 
462
        trace_file = open(temp_log_name, 'at')
 
463
        trace_file.writelines(['test_log_rollover padding\n'] * 200000)
 
464
        trace_file.close()
 
465
        _rollover_trace_maybe(temp_log_name)
 
466
        # should have been rolled over
 
467
        self.assertFalse(os.access(temp_log_name, os.R_OK))
 
468
 
 
469
 
 
470
class TestTraceConfiguration(TestCaseInTempDir):
 
471
 
 
472
    def test_default_config(self):
 
473
        config = trace.DefaultConfig()
 
474
        self.overrideAttr(trace, "_brz_log_filename", None)
 
475
        trace._brz_log_filename = None
 
476
        expected_filename = trace._get_brz_log_filename()
 
477
        self.assertEqual(None, trace._brz_log_filename)
 
478
        config.__enter__()
 
479
        try:
 
480
            # Should have entered and setup a default filename.
 
481
            self.assertEqual(expected_filename, trace._brz_log_filename)
 
482
        finally:
 
483
            config.__exit__(None, None, None)
 
484
            # Should have exited and cleaned up.
 
485
            self.assertEqual(None, trace._brz_log_filename)