~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to bzrlib/tests/test_trace.py

  • Committer: Jonathan Riddell
  • Date: 2011-09-27 14:06:24 UTC
  • mto: This revision was merged to the branch mainline in revision 6174.
  • Revision ID: jriddell@canonical.com-20110927140624-b2kx73ur01cu72il
use header format consistent with rest of bzr.  change copyright to canonical in line with copyright agreement

Show diffs side-by-side

added added

removed removed

Lines of Context:
 
1
# Copyright (C) 2005-2011 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
from cStringIO import StringIO
 
22
import errno
 
23
import os
 
24
import re
 
25
import sys
 
26
import tempfile
 
27
 
 
28
from bzrlib import (
 
29
    debug,
 
30
    errors,
 
31
    trace,
 
32
    )
 
33
from bzrlib.tests import features, TestCaseInTempDir, TestCase
 
34
from bzrlib.trace import (
 
35
    mutter, mutter_callsite, report_exception,
 
36
    set_verbosity_level, get_verbosity_level, is_quiet, is_verbose, be_quiet,
 
37
    pop_log_file,
 
38
    push_log_file,
 
39
    _rollover_trace_maybe,
 
40
    show_error,
 
41
    )
 
42
 
 
43
 
 
44
def _format_exception():
 
45
    """Format an exception as it would normally be displayed to the user"""
 
46
    buf = StringIO()
 
47
    report_exception(sys.exc_info(), buf)
 
48
    return buf.getvalue()
 
49
 
 
50
 
 
51
class TestTrace(TestCase):
 
52
 
 
53
    def test_format_sys_exception(self):
 
54
        # Test handling of an internal/unexpected error that probably
 
55
        # indicates a bug in bzr.  The details of the message may vary
 
56
        # depending on whether apport is available or not.  See test_crash for
 
57
        # more.
 
58
        try:
 
59
            raise NotImplementedError, "time travel"
 
60
        except NotImplementedError:
 
61
            pass
 
62
        err = _format_exception()
 
63
        self.assertEqualDiff(err.splitlines()[0],
 
64
                'bzr: ERROR: exceptions.NotImplementedError: time travel')
 
65
        self.assertContainsRe(err,
 
66
            'Bazaar has encountered an internal error.')
 
67
 
 
68
    def test_format_interrupt_exception(self):
 
69
        try:
 
70
            raise KeyboardInterrupt()
 
71
        except KeyboardInterrupt:
 
72
            # XXX: Some risk that a *real* keyboard interrupt won't be seen
 
73
            pass
 
74
        msg = _format_exception()
 
75
        self.assertTrue(len(msg) > 0)
 
76
        self.assertEqualDiff(msg, 'bzr: interrupted\n')
 
77
 
 
78
    def test_format_memory_error(self):
 
79
        try:
 
80
            raise MemoryError()
 
81
        except MemoryError:
 
82
            pass
 
83
        msg = _format_exception()
 
84
        self.assertEquals(msg,
 
85
            "bzr: out of memory\nUse -Dmem_dump to dump memory to a file.\n")
 
86
 
 
87
    def test_format_mem_dump(self):
 
88
        self.requireFeature(features.meliae)
 
89
        debug.debug_flags.add('mem_dump')
 
90
        try:
 
91
            raise MemoryError()
 
92
        except MemoryError:
 
93
            pass
 
94
        msg = _format_exception()
 
95
        self.assertStartsWith(msg,
 
96
            "bzr: out of memory\nMemory dumped to ")
 
97
 
 
98
    def test_format_os_error(self):
 
99
        try:
 
100
            os.rmdir('nosuchfile22222')
 
101
        except OSError, 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('bzr: ERROR: %s\n' % (e_str,), msg)
 
107
 
 
108
    def test_format_io_error(self):
 
109
        try:
 
110
            file('nosuchfile22222')
 
111
        except IOError:
 
112
            pass
 
113
        msg = _format_exception()
 
114
        # Even though Windows and Linux differ for 'os.rmdir', they both give
 
115
        # 'No such file' for open()
 
116
        # However it now gets translated so we can not test for a specific message
 
117
        self.assertContainsRe(msg,
 
118
            r'^bzr: ERROR: \[Errno .*\] .*nosuchfile')
 
119
 
 
120
    def test_format_pywintypes_error(self):
 
121
        self.requireFeature(features.pywintypes)
 
122
        import pywintypes, win32file
 
123
        try:
 
124
            win32file.RemoveDirectory('nosuchfile22222')
 
125
        except pywintypes.error:
 
126
            pass
 
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(msg,
 
131
            r"^bzr: ERROR: \(2, 'RemoveDirectory[AW]?', .*\)")
 
132
            
 
133
    def test_format_sockets_error(self):
 
134
        try:
 
135
            import socket
 
136
            sock = socket.socket()
 
137
            sock.send("This should fail.")
 
138
        except socket.error:
 
139
            pass
 
140
        msg = _format_exception()
 
141
        
 
142
        self.assertNotContainsRe(msg,
 
143
            r"Traceback (most recent call last):")
 
144
 
 
145
    def test_format_unicode_error(self):
 
146
        try:
 
147
            raise errors.BzrCommandError(u'argument foo\xb5 does not exist')
 
148
        except errors.BzrCommandError:
 
149
            pass
 
150
        msg = _format_exception()
 
151
 
 
152
    def test_format_exception(self):
 
153
        """Short formatting of bzr exceptions"""
 
154
        try:
 
155
            raise errors.NotBranchError('wibble')
 
156
        except errors.NotBranchError:
 
157
            pass
 
158
        msg = _format_exception()
 
159
        self.assertTrue(len(msg) > 0)
 
160
        self.assertEqualDiff(msg, 'bzr: ERROR: Not a branch: \"wibble\".\n')
 
161
 
 
162
    def test_report_external_import_error(self):
 
163
        """Short friendly message for missing system modules."""
 
164
        try:
 
165
            import ImaginaryModule
 
166
        except ImportError, e:
 
167
            pass
 
168
        else:
 
169
            self.fail("somehow succeeded in importing %r" % ImaginaryModule)
 
170
        msg = _format_exception()
 
171
        self.assertEqual(msg,
 
172
            'bzr: ERROR: No module named ImaginaryModule\n'
 
173
            'You may need to install this Python library separately.\n')
 
174
 
 
175
    def test_report_import_syntax_error(self):
 
176
        try:
 
177
            raise ImportError("syntax error")
 
178
        except ImportError, e:
 
179
            pass
 
180
        msg = _format_exception()
 
181
        self.assertContainsRe(msg,
 
182
            r'Bazaar has encountered an internal error')
 
183
 
 
184
    def test_trace_unicode(self):
 
185
        """Write Unicode to trace log"""
 
186
        self.log(u'the unicode character for benzene is \N{BENZENE RING}')
 
187
        log = self.get_log()
 
188
        self.assertContainsRe(log, "the unicode character for benzene is")
 
189
 
 
190
    def test_trace_argument_unicode(self):
 
191
        """Write a Unicode argument to the trace log"""
 
192
        mutter(u'the unicode character for benzene is %s', u'\N{BENZENE RING}')
 
193
        log = self.get_log()
 
194
        self.assertContainsRe(log, 'the unicode character')
 
195
 
 
196
    def test_trace_argument_utf8(self):
 
197
        """Write a Unicode argument to the trace log"""
 
198
        mutter(u'the unicode character for benzene is %s',
 
199
               u'\N{BENZENE RING}'.encode('utf-8'))
 
200
        log = self.get_log()
 
201
        self.assertContainsRe(log, 'the unicode character')
 
202
 
 
203
    def test_report_broken_pipe(self):
 
204
        try:
 
205
            raise IOError(errno.EPIPE, 'broken pipe foofofo')
 
206
        except IOError, e:
 
207
            msg = _format_exception()
 
208
            self.assertEquals(msg, "bzr: broken pipe\n")
 
209
        else:
 
210
            self.fail("expected error not raised")
 
211
 
 
212
    def assertLogStartsWith(self, log, string):
 
213
        """Like assertStartsWith, but skips the log timestamp."""
 
214
        self.assertContainsRe(log,
 
215
            '^\\d+\\.\\d+  ' + re.escape(string))
 
216
 
 
217
    def test_mutter_callsite_1(self):
 
218
        """mutter_callsite can capture 1 level of stack frame."""
 
219
        mutter_callsite(1, "foo %s", "a string")
 
220
        log = self.get_log()
 
221
        # begin with the message
 
222
        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
 
223
        # should show two frame: this frame and the one above
 
224
        self.assertContainsRe(log,
 
225
            'test_trace\\.py", line \\d+, in test_mutter_callsite_1\n')
 
226
        # this frame should be the final one
 
227
        self.assertEndsWith(log, ' "a string")\n')
 
228
 
 
229
    def test_mutter_callsite_2(self):
 
230
        """mutter_callsite can capture 2 levels of stack frame."""
 
231
        mutter_callsite(2, "foo %s", "a string")
 
232
        log = self.get_log()
 
233
        # begin with the message
 
234
        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
 
235
        # should show two frame: this frame and the one above
 
236
        self.assertContainsRe(log,
 
237
            'test_trace.py", line \d+, in test_mutter_callsite_2\n')
 
238
        # this frame should be the final one
 
239
        self.assertEndsWith(log, ' "a string")\n')
 
240
 
 
241
    def test_mutter_never_fails(self):
 
242
        # Even if the decode/encode stage fails, mutter should not
 
243
        # raise an exception
 
244
        # This test checks that mutter doesn't fail; the current behaviour
 
245
        # is that it doesn't fail *and writes non-utf8*.
 
246
        mutter(u'Writing a greek mu (\xb5) works in a unicode string')
 
247
        mutter('But fails in an ascii string \xb5')
 
248
        mutter('and in an ascii argument: %s', '\xb5')
 
249
        log = self.get_log()
 
250
        self.assertContainsRe(log, 'Writing a greek mu')
 
251
        self.assertContainsRe(log, "But fails in an ascii string")
 
252
        # However, the log content object does unicode replacement on reading
 
253
        # to let it get unicode back where good data has been written. So we
 
254
        # have to do a replaceent here as well.
 
255
        self.assertContainsRe(log, "ascii argument: \xb5".decode('utf8',
 
256
            'replace'))
 
257
        
 
258
    def test_show_error(self):
 
259
        show_error('error1')
 
260
        show_error(u'error2 \xb5 blah')
 
261
        show_error('arg: %s', 'blah')
 
262
        show_error('arg2: %(key)s', {'key':'stuff'})
 
263
        try:
 
264
            raise Exception("oops")
 
265
        except:
 
266
            show_error('kwarg', exc_info=True)
 
267
        log = self.get_log()
 
268
        self.assertContainsRe(log, 'error1')
 
269
        self.assertContainsRe(log, u'error2 \xb5 blah')
 
270
        self.assertContainsRe(log, 'arg: blah')
 
271
        self.assertContainsRe(log, 'arg2: stuff')
 
272
        self.assertContainsRe(log, 'kwarg')
 
273
        self.assertContainsRe(log, 'Traceback \\(most recent call last\\):')
 
274
        self.assertContainsRe(log, 'File ".*test_trace.py", line .*, in test_show_error')
 
275
        self.assertContainsRe(log, 'raise Exception\\("oops"\\)')
 
276
        self.assertContainsRe(log, 'Exception: oops')
 
277
 
 
278
    def test_push_log_file(self):
 
279
        """Can push and pop log file, and this catches mutter messages.
 
280
 
 
281
        This is primarily for use in the test framework.
 
282
        """
 
283
        tmp1 = tempfile.NamedTemporaryFile()
 
284
        tmp2 = tempfile.NamedTemporaryFile()
 
285
        try:
 
286
            memento1 = push_log_file(tmp1)
 
287
            mutter("comment to file1")
 
288
            try:
 
289
                memento2 = push_log_file(tmp2)
 
290
                try:
 
291
                    mutter("comment to file2")
 
292
                finally:
 
293
                    pop_log_file(memento2)
 
294
                mutter("again to file1")
 
295
            finally:
 
296
                pop_log_file(memento1)
 
297
            # the files were opened in binary mode, so should have exactly
 
298
            # these bytes.  and removing the file as the log target should
 
299
            # have caused them to be flushed out.  need to match using regexps
 
300
            # as there's a timestamp at the front.
 
301
            tmp1.seek(0)
 
302
            self.assertContainsRe(tmp1.read(),
 
303
                r"\d+\.\d+  comment to file1\n\d+\.\d+  again to file1\n")
 
304
            tmp2.seek(0)
 
305
            self.assertContainsRe(tmp2.read(),
 
306
                r"\d+\.\d+  comment to file2\n")
 
307
        finally:
 
308
            tmp1.close()
 
309
            tmp2.close()
 
310
 
 
311
    def test__open_bzr_log_uses_stderr_for_failures(self):
 
312
        # If _open_bzr_log cannot open the file, then we should write the
 
313
        # warning to stderr. Since this is normally happening before logging is
 
314
        # set up.
 
315
        self.overrideAttr(sys, 'stderr', StringIO())
 
316
        # Set the log file to something that cannot exist
 
317
        self.overrideEnv('BZR_LOG', os.getcwd() + '/no-dir/bzr.log')
 
318
        self.overrideAttr(trace, '_bzr_log_filename')
 
319
        logf = trace._open_bzr_log()
 
320
        self.assertIs(None, logf)
 
321
        self.assertContainsRe(sys.stderr.getvalue(),
 
322
                              'failed to open trace file: .*/no-dir/bzr.log')
 
323
 
 
324
 
 
325
class TestVerbosityLevel(TestCase):
 
326
 
 
327
    def test_verbosity_level(self):
 
328
        set_verbosity_level(1)
 
329
        self.assertEqual(1, get_verbosity_level())
 
330
        self.assertTrue(is_verbose())
 
331
        self.assertFalse(is_quiet())
 
332
        set_verbosity_level(-1)
 
333
        self.assertEqual(-1, get_verbosity_level())
 
334
        self.assertFalse(is_verbose())
 
335
        self.assertTrue(is_quiet())
 
336
        set_verbosity_level(0)
 
337
        self.assertEqual(0, get_verbosity_level())
 
338
        self.assertFalse(is_verbose())
 
339
        self.assertFalse(is_quiet())
 
340
 
 
341
    def test_be_quiet(self):
 
342
        # Confirm the old API still works
 
343
        be_quiet(True)
 
344
        self.assertEqual(-1, get_verbosity_level())
 
345
        be_quiet(False)
 
346
        self.assertEqual(0, get_verbosity_level())
 
347
 
 
348
 
 
349
class TestBzrLog(TestCaseInTempDir):
 
350
 
 
351
    def test_log_rollover(self):
 
352
        temp_log_name = 'test-log'
 
353
        trace_file = open(temp_log_name, 'at')
 
354
        trace_file.writelines(['test_log_rollover padding\n'] * 200000)
 
355
        trace_file.close()
 
356
        _rollover_trace_maybe(temp_log_name)
 
357
        # should have been rolled over
 
358
        self.assertFalse(os.access(temp_log_name, os.R_OK))
 
359
 
 
360
 
 
361
class TestTraceConfiguration(TestCaseInTempDir):
 
362
 
 
363
    def test_default_config(self):
 
364
        config = trace.DefaultConfig()
 
365
        self.overrideAttr(trace, "_bzr_log_filename", None)
 
366
        trace._bzr_log_filename = None
 
367
        expected_filename = trace._get_bzr_log_filename()
 
368
        self.assertEqual(None, trace._bzr_log_filename)
 
369
        config.__enter__()
 
370
        try:
 
371
            # Should have entered and setup a default filename.
 
372
            self.assertEqual(expected_filename, trace._bzr_log_filename)
 
373
        finally:
 
374
            config.__exit__(None, None, None)
 
375
            # Should have exited and cleaned up.
 
376
            self.assertEqual(None, trace._bzr_log_filename)