/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: 2017-06-10 16:40:42 UTC
  • mfrom: (6653.6.7 rename-controldir)
  • mto: This revision was merged to the branch mainline in revision 6690.
  • Revision ID: jelmer@jelmer.uk-20170610164042-zrxqgy2htyduvke2
Merge rename-controldir branch.

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
    BytesIO,
 
35
    )
 
36
from . import features, TestCaseInTempDir, TestCase
 
37
from ..trace import (
 
38
    mutter, mutter_callsite, report_exception,
 
39
    set_verbosity_level, get_verbosity_level, is_quiet, is_verbose, be_quiet,
 
40
    pop_log_file,
 
41
    push_log_file,
 
42
    _rollover_trace_maybe,
 
43
    show_error,
 
44
    )
 
45
 
 
46
 
 
47
def _format_exception():
 
48
    """Format an exception as it would normally be displayed to the user"""
 
49
    buf = BytesIO()
 
50
    report_exception(sys.exc_info(), buf)
 
51
    return buf.getvalue()
 
52
 
 
53
 
 
54
class TestTrace(TestCase):
 
55
 
 
56
    def test_format_sys_exception(self):
 
57
        # Test handling of an internal/unexpected error that probably
 
58
        # indicates a bug in brz.  The details of the message may vary
 
59
        # depending on whether apport is available or not.  See test_crash for
 
60
        # more.
 
61
        try:
 
62
            raise NotImplementedError("time travel")
 
63
        except NotImplementedError:
 
64
            pass
 
65
        err = _format_exception()
 
66
        self.assertEqualDiff(err.splitlines()[0],
 
67
                'brz: ERROR: exceptions.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
            pass
 
77
        msg = _format_exception()
 
78
        self.assertTrue(len(msg) > 0)
 
79
        self.assertEqualDiff(msg, 'brz: interrupted\n')
 
80
 
 
81
    def test_format_memory_error(self):
 
82
        try:
 
83
            raise MemoryError()
 
84
        except MemoryError:
 
85
            pass
 
86
        msg = _format_exception()
 
87
        self.assertEqual(msg,
 
88
            "brz: out of memory\nUse -Dmem_dump to dump memory to a file.\n")
 
89
 
 
90
    def test_format_mem_dump(self):
 
91
        self.requireFeature(features.meliae)
 
92
        debug.debug_flags.add('mem_dump')
 
93
        try:
 
94
            raise MemoryError()
 
95
        except MemoryError:
 
96
            pass
 
97
        msg = _format_exception()
 
98
        self.assertStartsWith(msg,
 
99
            "brz: out of memory\nMemory dumped to ")
 
100
 
 
101
    def test_format_os_error(self):
 
102
        try:
 
103
            os.rmdir('nosuchfile22222')
 
104
        except OSError as e:
 
105
            e_str = str(e)
 
106
        msg = _format_exception()
 
107
        # Linux seems to give "No such file" but Windows gives "The system
 
108
        # cannot find the file specified".
 
109
        self.assertEqual('brz: ERROR: %s\n' % (e_str,), msg)
 
110
 
 
111
    def test_format_io_error(self):
 
112
        try:
 
113
            file('nosuchfile22222')
 
114
        except IOError:
 
115
            pass
 
116
        msg = _format_exception()
 
117
        # Even though Windows and Linux differ for 'os.rmdir', they both give
 
118
        # 'No such file' for open()
 
119
        # However it now gets translated so we can not test for a specific message
 
120
        self.assertContainsRe(msg,
 
121
            r'^brz: ERROR: \[Errno .*\] .*nosuchfile')
 
122
 
 
123
    def test_format_pywintypes_error(self):
 
124
        self.requireFeature(features.pywintypes)
 
125
        import pywintypes, win32file
 
126
        try:
 
127
            win32file.RemoveDirectory('nosuchfile22222')
 
128
        except pywintypes.error:
 
129
            pass
 
130
        msg = _format_exception()
 
131
        # GZ 2010-05-03: Formatting for pywintypes.error is basic, a 3-tuple
 
132
        #                with errno, function name, and locale error message
 
133
        self.assertContainsRe(msg,
 
134
            r"^brz: ERROR: \(2, 'RemoveDirectory[AW]?', .*\)")
 
135
            
 
136
    def test_format_sockets_error(self):
 
137
        try:
 
138
            import socket
 
139
            sock = socket.socket()
 
140
            sock.send("This should fail.")
 
141
        except socket.error:
 
142
            pass
 
143
        msg = _format_exception()
 
144
        
 
145
        self.assertNotContainsRe(msg,
 
146
            r"Traceback (most recent call last):")
 
147
 
 
148
    def test_format_unicode_error(self):
 
149
        try:
 
150
            raise errors.BzrCommandError(u'argument foo\xb5 does not exist')
 
151
        except errors.BzrCommandError:
 
152
            pass
 
153
        msg = _format_exception()
 
154
 
 
155
    def test_format_exception(self):
 
156
        """Short formatting of brz exceptions"""
 
157
        try:
 
158
            raise errors.NotBranchError('wibble')
 
159
        except errors.NotBranchError:
 
160
            pass
 
161
        msg = _format_exception()
 
162
        self.assertTrue(len(msg) > 0)
 
163
        self.assertEqualDiff(msg, 'brz: ERROR: Not a branch: \"wibble\".\n')
 
164
 
 
165
    def test_report_external_import_error(self):
 
166
        """Short friendly message for missing system modules."""
 
167
        try:
 
168
            import ImaginaryModule
 
169
        except ImportError as e:
 
170
            pass
 
171
        else:
 
172
            self.fail("somehow succeeded in importing %r" % ImaginaryModule)
 
173
        msg = _format_exception()
 
174
        self.assertEqual(msg,
 
175
            'brz: ERROR: No module named ImaginaryModule\n'
 
176
            'You may need to install this Python library separately.\n')
 
177
 
 
178
    def test_report_import_syntax_error(self):
 
179
        try:
 
180
            raise ImportError("syntax error")
 
181
        except ImportError as e:
 
182
            pass
 
183
        msg = _format_exception()
 
184
        self.assertContainsRe(msg,
 
185
            r'Bazaar has encountered an internal error')
 
186
 
 
187
    def test_trace_unicode(self):
 
188
        """Write Unicode to trace log"""
 
189
        self.log(u'the unicode character for benzene is \N{BENZENE RING}')
 
190
        log = self.get_log()
 
191
        self.assertContainsRe(log, "the unicode character for benzene is")
 
192
 
 
193
    def test_trace_argument_unicode(self):
 
194
        """Write a Unicode argument to the trace log"""
 
195
        mutter(u'the unicode character for benzene is %s', u'\N{BENZENE RING}')
 
196
        log = self.get_log()
 
197
        self.assertContainsRe(log, 'the unicode character')
 
198
 
 
199
    def test_trace_argument_utf8(self):
 
200
        """Write a Unicode argument to the trace log"""
 
201
        mutter(u'the unicode character for benzene is %s',
 
202
               u'\N{BENZENE RING}'.encode('utf-8'))
 
203
        log = self.get_log()
 
204
        self.assertContainsRe(log, 'the unicode character')
 
205
 
 
206
    def test_report_broken_pipe(self):
 
207
        try:
 
208
            raise IOError(errno.EPIPE, 'broken pipe foofofo')
 
209
        except IOError as e:
 
210
            msg = _format_exception()
 
211
            self.assertEqual(msg, "brz: broken pipe\n")
 
212
        else:
 
213
            self.fail("expected error not raised")
 
214
 
 
215
    def assertLogStartsWith(self, log, string):
 
216
        """Like assertStartsWith, but skips the log timestamp."""
 
217
        self.assertContainsRe(log,
 
218
            '^\\d+\\.\\d+  ' + re.escape(string))
 
219
 
 
220
    def test_mutter_callsite_1(self):
 
221
        """mutter_callsite can capture 1 level of stack frame."""
 
222
        mutter_callsite(1, "foo %s", "a string")
 
223
        log = self.get_log()
 
224
        # begin with the message
 
225
        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
 
226
        # should show two frame: this frame and the one above
 
227
        self.assertContainsRe(log,
 
228
            'test_trace\\.py", line \\d+, in test_mutter_callsite_1\n')
 
229
        # this frame should be the final one
 
230
        self.assertEndsWith(log, ' "a string")\n')
 
231
 
 
232
    def test_mutter_callsite_2(self):
 
233
        """mutter_callsite can capture 2 levels of stack frame."""
 
234
        mutter_callsite(2, "foo %s", "a string")
 
235
        log = self.get_log()
 
236
        # begin with the message
 
237
        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
 
238
        # should show two frame: this frame and the one above
 
239
        self.assertContainsRe(log,
 
240
            'test_trace.py", line \d+, in test_mutter_callsite_2\n')
 
241
        # this frame should be the final one
 
242
        self.assertEndsWith(log, ' "a string")\n')
 
243
 
 
244
    def test_mutter_never_fails(self):
 
245
        # Even if the decode/encode stage fails, mutter should not
 
246
        # raise an exception
 
247
        # This test checks that mutter doesn't fail; the current behaviour
 
248
        # is that it doesn't fail *and writes non-utf8*.
 
249
        mutter(u'Writing a greek mu (\xb5) works in a unicode string')
 
250
        mutter('But fails in an ascii string \xb5')
 
251
        mutter('and in an ascii argument: %s', '\xb5')
 
252
        log = self.get_log()
 
253
        self.assertContainsRe(log, 'Writing a greek mu')
 
254
        self.assertContainsRe(log, "But fails in an ascii string")
 
255
        # However, the log content object does unicode replacement on reading
 
256
        # to let it get unicode back where good data has been written. So we
 
257
        # have to do a replaceent here as well.
 
258
        self.assertContainsRe(log, "ascii argument: \xb5".decode('utf8',
 
259
            'replace'))
 
260
 
 
261
    def test_show_error(self):
 
262
        show_error('error1')
 
263
        show_error(u'error2 \xb5 blah')
 
264
        show_error('arg: %s', 'blah')
 
265
        show_error('arg2: %(key)s', {'key':'stuff'})
 
266
        try:
 
267
            raise Exception("oops")
 
268
        except:
 
269
            show_error('kwarg', exc_info=True)
 
270
        log = self.get_log()
 
271
        self.assertContainsRe(log, 'error1')
 
272
        self.assertContainsRe(log, u'error2 \xb5 blah')
 
273
        self.assertContainsRe(log, 'arg: blah')
 
274
        self.assertContainsRe(log, 'arg2: stuff')
 
275
        self.assertContainsRe(log, 'kwarg')
 
276
        self.assertContainsRe(log, 'Traceback \\(most recent call last\\):')
 
277
        self.assertContainsRe(log, 'File ".*test_trace.py", line .*, in test_show_error')
 
278
        self.assertContainsRe(log, 'raise Exception\\("oops"\\)')
 
279
        self.assertContainsRe(log, 'Exception: oops')
 
280
 
 
281
    def test_push_log_file(self):
 
282
        """Can push and pop log file, and this catches mutter messages.
 
283
 
 
284
        This is primarily for use in the test framework.
 
285
        """
 
286
        tmp1 = tempfile.NamedTemporaryFile()
 
287
        tmp2 = tempfile.NamedTemporaryFile()
 
288
        try:
 
289
            memento1 = push_log_file(tmp1)
 
290
            mutter("comment to file1")
 
291
            try:
 
292
                memento2 = push_log_file(tmp2)
 
293
                try:
 
294
                    mutter("comment to file2")
 
295
                finally:
 
296
                    pop_log_file(memento2)
 
297
                mutter("again to file1")
 
298
            finally:
 
299
                pop_log_file(memento1)
 
300
            # the files were opened in binary mode, so should have exactly
 
301
            # these bytes.  and removing the file as the log target should
 
302
            # have caused them to be flushed out.  need to match using regexps
 
303
            # as there's a timestamp at the front.
 
304
            tmp1.seek(0)
 
305
            self.assertContainsRe(tmp1.read(),
 
306
                r"\d+\.\d+  comment to file1\n\d+\.\d+  again to file1\n")
 
307
            tmp2.seek(0)
 
308
            self.assertContainsRe(tmp2.read(),
 
309
                r"\d+\.\d+  comment to file2\n")
 
310
        finally:
 
311
            tmp1.close()
 
312
            tmp2.close()
 
313
 
 
314
    def test__open_brz_log_uses_stderr_for_failures(self):
 
315
        # If _open_brz_log cannot open the file, then we should write the
 
316
        # warning to stderr. Since this is normally happening before logging is
 
317
        # set up.
 
318
        self.overrideAttr(sys, 'stderr', BytesIO())
 
319
        # Set the log file to something that cannot exist
 
320
        self.overrideEnv('BRZ_LOG', '/no-such-dir/brz.log')
 
321
        self.overrideAttr(trace, '_brz_log_filename')
 
322
        logf = trace._open_brz_log()
 
323
        self.assertIs(None, logf)
 
324
        self.assertContainsRe(
 
325
            sys.stderr.getvalue(),
 
326
            "failed to open trace file: .* '/no-such-dir/brz.log'$")
 
327
 
 
328
 
 
329
class TestVerbosityLevel(TestCase):
 
330
 
 
331
    def test_verbosity_level(self):
 
332
        set_verbosity_level(1)
 
333
        self.assertEqual(1, get_verbosity_level())
 
334
        self.assertTrue(is_verbose())
 
335
        self.assertFalse(is_quiet())
 
336
        set_verbosity_level(-1)
 
337
        self.assertEqual(-1, get_verbosity_level())
 
338
        self.assertFalse(is_verbose())
 
339
        self.assertTrue(is_quiet())
 
340
        set_verbosity_level(0)
 
341
        self.assertEqual(0, get_verbosity_level())
 
342
        self.assertFalse(is_verbose())
 
343
        self.assertFalse(is_quiet())
 
344
 
 
345
    def test_be_quiet(self):
 
346
        # Confirm the old API still works
 
347
        be_quiet(True)
 
348
        self.assertEqual(-1, get_verbosity_level())
 
349
        be_quiet(False)
 
350
        self.assertEqual(0, get_verbosity_level())
 
351
 
 
352
 
 
353
class TestLogging(TestCase):
 
354
    """Check logging functionality robustly records information"""
 
355
 
 
356
    def test_note(self):
 
357
        trace.note("Noted")
 
358
        self.assertEqual("    INFO  Noted\n", self.get_log())
 
359
 
 
360
    def test_warning(self):
 
361
        trace.warning("Warned")
 
362
        self.assertEqual(" WARNING  Warned\n", self.get_log())
 
363
 
 
364
    def test_log(self):
 
365
        logging.getLogger("brz").error("Errored")
 
366
        self.assertEqual("   ERROR  Errored\n", self.get_log())
 
367
 
 
368
    def test_log_sub(self):
 
369
        logging.getLogger("brz.test_log_sub").debug("Whispered")
 
370
        self.assertEqual("   DEBUG  Whispered\n", self.get_log())
 
371
 
 
372
    def test_log_unicode_msg(self):
 
373
        logging.getLogger("brz").debug(u"\xa7")
 
374
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
375
 
 
376
    def test_log_unicode_arg(self):
 
377
        logging.getLogger("brz").debug("%s", u"\xa7")
 
378
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
379
 
 
380
    def test_log_utf8_msg(self):
 
381
        logging.getLogger("brz").debug("\xc2\xa7")
 
382
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
383
 
 
384
    def test_log_utf8_arg(self):
 
385
        logging.getLogger("brz").debug("%s", "\xc2\xa7")
 
386
        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
387
 
 
388
    def test_log_bytes_msg(self):
 
389
        logging.getLogger("brz").debug("\xa7")
 
390
        log = self.get_log()
 
391
        self.assertContainsString(log, "UnicodeDecodeError: ")
 
392
        self.assertContainsString(log,
 
393
            "Logging record unformattable: '\\xa7' % ()\n")
 
394
 
 
395
    def test_log_bytes_arg(self):
 
396
        logging.getLogger("brz").debug("%s", "\xa7")
 
397
        log = self.get_log()
 
398
        self.assertContainsString(log, "UnicodeDecodeError: ")
 
399
        self.assertContainsString(log,
 
400
            "Logging record unformattable: '%s' % ('\\xa7',)\n")
 
401
 
 
402
    def test_log_mixed_strings(self):
 
403
        logging.getLogger("brz").debug(u"%s", "\xa7")
 
404
        log = self.get_log()
 
405
        self.assertContainsString(log, "UnicodeDecodeError: ")
 
406
        self.assertContainsString(log,
 
407
            "Logging record unformattable: u'%s' % ('\\xa7',)\n")
 
408
 
 
409
    def test_log_repr_broken(self):
 
410
        class BadRepr(object):
 
411
            def __repr__(self):
 
412
                raise ValueError("Broken object")
 
413
        logging.getLogger("brz").debug("%s", BadRepr())
 
414
        log = self.get_log()
 
415
        self.assertContainsRe(log, "ValueError: Broken object\n")
 
416
        self.assertContainsRe(log, "Logging record unformattable: '%s' % .*\n")
 
417
 
 
418
 
 
419
class TestBzrLog(TestCaseInTempDir):
 
420
 
 
421
    def test_log_rollover(self):
 
422
        temp_log_name = 'test-log'
 
423
        trace_file = open(temp_log_name, 'at')
 
424
        trace_file.writelines(['test_log_rollover padding\n'] * 200000)
 
425
        trace_file.close()
 
426
        _rollover_trace_maybe(temp_log_name)
 
427
        # should have been rolled over
 
428
        self.assertFalse(os.access(temp_log_name, os.R_OK))
 
429
 
 
430
 
 
431
class TestTraceConfiguration(TestCaseInTempDir):
 
432
 
 
433
    def test_default_config(self):
 
434
        config = trace.DefaultConfig()
 
435
        self.overrideAttr(trace, "_brz_log_filename", None)
 
436
        trace._brz_log_filename = None
 
437
        expected_filename = trace._get_brz_log_filename()
 
438
        self.assertEqual(None, trace._brz_log_filename)
 
439
        config.__enter__()
 
440
        try:
 
441
            # Should have entered and setup a default filename.
 
442
            self.assertEqual(expected_filename, trace._brz_log_filename)
 
443
        finally:
 
444
            config.__exit__(None, None, None)
 
445
            # Should have exited and cleaned up.
 
446
            self.assertEqual(None, trace._brz_log_filename)