Unstable nosetests wrt login

[Thomas De Schampheleire]

On Sun, Feb 22, 2015 at 5:06 PM, Mads Kiilerich <mads at kiilerich.com> wrote:
> On 02/22/2015 12:29 PM, Thomas De Schampheleire wrote:
>>
>> Hi,
>>
>> When running nosetests, I sometimes see a few tests failing,
>> inconsistently. The errors are:
>>
>> ======================================================================
>> ERROR: test_index_with_anonymous_access_disabled
>> (kallithea.tests.functional.test_home.TestHomeController)
>> ----------------------------------------------------------------------
>> Traceback (most recent call last):
>>    File
>> "/home/tdescham/repo/contrib/kallithea/kallithea/tests/functional/test_home.py",
>> line 42, in test_index_with_anonymous_access_disabled
>>      status=302)
>>    File
>> "/home/tdescham/repo/contrib/kallithea/dist/v/local/lib/python2.7/site-packages/WebTest-1.4.3-py2.7.egg/webtest/app.py",
>> line 759, in get
>>      expect_errors=expect_errors)
>> ...
>> ----------------------------------------------------------------------
>> Ran 1507 tests in 700.694s
>>
>> FAILED (SKIP=5, errors=4)
>>
>>
>> So it looks like an access that is supposed to be blocked is allowed
>> anyhow.
>>
>> Running the tests again typically 'solves' the problem.
>> I tried running the offending tests over and over again, but it does
>> not reproduce.
>>
>> I have seen this issue several times already, but very inconsistently.
>>
>> Is anyone else seeing this?
>> Is it a test problem or rather a Kallithea bug?
>
>
> I might have seen it a few times but not so often or reproducible that I can
> reproduce it.
>
> The tests are not unit tests and are not isolated and cannot be run in
> parallel ... but we are always running them in the same sequence so it
> should be stable.
>

Mads mentioned on IRC that he has been seeing these issues too now.
I have updated to 0.1 to check if the issue was present there too, and
it's the case.

A script that can be used to detect the problem is:

#!/bin/bash
i=0;
while true; do
    echo "RUN $i";
    let 'i+=1';
    nosetests \
        kallithea.tests.functional.test_feed \
        kallithea.tests.functional.test_files \
        kallithea.tests.functional.test_followers \
        kallithea.tests.functional.test_forks \
        kallithea.tests.functional.test_home;
done

If you run this, send the output to a logfile, and grep on
'RUN|FAILED' then you will see the errors when they pop up.

The special thing about the tests I see is that they use
fixture.anon_access, which is implemented as:

    def anon_access(self, status):
        """
        Context process for disabling anonymous access. use like:
        fixture = Fixture()
        with fixture.anon_access(False):
            #tests

        after this block anon access will be set to `not status`
        """

        class context(object):
            def __enter__(self):
                anon = User.get_default_user()
                anon.active = status
                Session().add(anon)
                Session().commit()
                time.sleep(1.5)  # must sleep for cache (1s to expire)

            def __exit__(self, exc_type, exc_val, exc_tb):
                anon = User.get_default_user()
                anon.active = not status
                Session().add(anon)
                Session().commit()

        return context()


The suspicious item in this code is:
    "time.sleep(1.5)  # must sleep for cache (1s to expire)"

I am not convinced about the correctness of sleeping for some
arbitrary time to let a cache expire. Invalidating the cache
explicitly would yield deterministic results.

Which cache is this really?
Any idea on how to invalidate it?

Thanks,
Thomas