tests/test-util.py
author Gregory Szorc <gregory.szorc@gmail.com>
Tue, 13 Nov 2018 12:32:05 -0800
changeset 40671 e9293c5f8bb9
parent 39286 331ab85e910b
child 43076 2372284d9457
permissions -rw-r--r--
revlog: automatically read from opened file handles The revlog reading code commonly opens a new file handle for reading on demand. There is support for passing a file handle to revlog.revision(). But it is marked as an internal argument. When revlogs are written, we write() data as it is available. But we don't flush() data until all revisions are written. Putting these two traits together, it is possible for an in-process revlog reader during active writes to trigger the opening of a new file handle on a file with unflushed writes. The reader won't have access to all "available" revlog data (as it hasn't been flushed). And with the introduction of the previous patch, this can lead to the revlog raising an error due to a partial read. I witnessed this behavior when applying changegroup data (via `hg pull`) before issue6006 was fixed via different means. Having this and the previous patch in play would have helped cause errors earlier rather than manifesting as hash verification failures. While this has been a long-standing issue, I believe the relatively new delta computation code has tickled it into being more common. This is because the new delta computation code will compute deltas in more scenarios. This can lead to revlog reading. While the delta computation code is probably supposed to reuse file handles, it appears it isn't doing so in all circumstances. But the issue runs deeper than that. Theoretically, any code can access revision data during revlog writes. It appears we were just getting lucky that it wasn't. (The "add revision callback" passed to addgroup() provides an avenue to do this.) If I changed the revlog's behavior to not cache the full revision text or to clear caches after revision insertion during addgroup(), I was able to produce crashes 100% of the time when writing changelog revisions. This is because changelog's add revision callback attempts to resolve the revision data to access the changed files list. And without the revision's fulltext being cached, we performed a revlog read, which required opening a new file handle. This attempted to read unflushed data, leading to a partial read and a crash. This commit teaches the revlog to store the file handles used for writing multiple revisions during addgroup(). It also teaches the code for resolving a file handle when reading to use these handles, if available. This ensures that *any* reads (regardless of their source) use the active writing file handles, if available. These file handles have access to the unflushed data because they wrote it. This allows reads to complete without issue. Differential Revision: https://phab.mercurial-scm.org/D5267

# unit tests for mercuril.util utilities
from __future__ import absolute_import

import contextlib
import itertools
import unittest

from mercurial import pycompat, util, utils

@contextlib.contextmanager
def mocktimer(incr=0.1, *additional_targets):
    """Replaces util.timer and additional_targets with a mock

    The timer starts at 0. On each call the time incremented by the value
    of incr. If incr is an iterable, then the time is incremented by the
    next value from that iterable, looping in a cycle when reaching the end.

    additional_targets must be a sequence of (object, attribute_name) tuples;
    the mock is set with setattr(object, attribute_name, mock).

    """
    time = [0]
    try:
        incr = itertools.cycle(incr)
    except TypeError:
        incr = itertools.repeat(incr)

    def timer():
        time[0] += next(incr)
        return time[0]

    # record original values
    orig = util.timer
    additional_origs = [(o, a, getattr(o, a)) for o, a in additional_targets]

    # mock out targets
    util.timer = timer
    for obj, attr in additional_targets:
        setattr(obj, attr, timer)

    try:
        yield
    finally:
        # restore originals
        util.timer = orig
        for args in additional_origs:
            setattr(*args)

# attr.s default factory for util.timedstats.start binds the timer we
# need to mock out.
_start_default = (util.timedcmstats.start.default, 'factory')

@contextlib.contextmanager
def capturestderr():
    """Replace utils.procutil.stderr with a pycompat.bytesio instance

    The instance is made available as the return value of __enter__.

    This contextmanager is reentrant.

    """
    orig = utils.procutil.stderr
    utils.procutil.stderr = pycompat.bytesio()
    try:
        yield utils.procutil.stderr
    finally:
        utils.procutil.stderr = orig

class timedtests(unittest.TestCase):
    def testtimedcmstatsstr(self):
        stats = util.timedcmstats()
        self.assertEqual(str(stats), '<unknown>')
        self.assertEqual(bytes(stats), b'<unknown>')
        stats.elapsed = 12.34
        self.assertEqual(str(stats), pycompat.sysstr(util.timecount(12.34)))
        self.assertEqual(bytes(stats), util.timecount(12.34))

    def testtimedcmcleanexit(self):
        # timestamps 1, 4, elapsed time of 4 - 1 = 3
        with mocktimer([1, 3], _start_default):
            with util.timedcm('pass') as stats:
                # actual context doesn't matter
                pass

        self.assertEqual(stats.start, 1)
        self.assertEqual(stats.elapsed, 3)
        self.assertEqual(stats.level, 1)

    def testtimedcmnested(self):
        # timestamps 1, 3, 6, 10, elapsed times of 6 - 3 = 3 and 10 - 1 = 9
        with mocktimer([1, 2, 3, 4], _start_default):
            with util.timedcm('outer') as outer_stats:
                with util.timedcm('inner') as inner_stats:
                    # actual context doesn't matter
                    pass

        self.assertEqual(outer_stats.start, 1)
        self.assertEqual(outer_stats.elapsed, 9)
        self.assertEqual(outer_stats.level, 1)

        self.assertEqual(inner_stats.start, 3)
        self.assertEqual(inner_stats.elapsed, 3)
        self.assertEqual(inner_stats.level, 2)

    def testtimedcmexception(self):
        # timestamps 1, 4, elapsed time of 4 - 1 = 3
        with mocktimer([1, 3], _start_default):
            try:
                with util.timedcm('exceptional') as stats:
                    raise ValueError()
            except ValueError:
                pass

        self.assertEqual(stats.start, 1)
        self.assertEqual(stats.elapsed, 3)
        self.assertEqual(stats.level, 1)

    def testtimeddecorator(self):
        @util.timed
        def testfunc(callcount=1):
            callcount -= 1
            if callcount:
                testfunc(callcount)

        # timestamps 1, 2, 3, 4, elapsed time of 3 - 2 = 1 and 4 - 1 = 3
        with mocktimer(1, _start_default):
            with capturestderr() as out:
                testfunc(2)

        self.assertEqual(out.getvalue(), (
            b'    testfunc: 1.000 s\n'
            b'  testfunc: 3.000 s\n'
        ))

if __name__ == '__main__':
    import silenttestrunner
    silenttestrunner.main(__name__)