Inconsistent behavior of pytest.deprecated_call()

[netme]

We are currently upgrading py.test from 2.7.1 to 2.8.3 . We have found a small inconsistency in pytest.deprecated_call() behaviour.

We have few tests which are calling deprecated methods in our codebase. And afterwards we have few tests which are checking that the methods are deprecated. Running that tests on 2.7.1 produce no issues. After switching to 2.8.3, we have found out that the tests which are using pytest.deprecated_call() started failing. Here is an example:

import warnings

import pytest


def deprecated_function():
    warnings.warn("deprecated", DeprecationWarning)


def test_one():
    deprecated_function()


def test_two():
    pytest.deprecated_call(deprecated_function)

When running it on 2.8.3, the following AssertionError is raised:

    def test_two():
>       pytest.deprecated_call(deprecated_function)
E       AssertionError: <function deprecated_function at 0x10ac51a28> did not produce DeprecationWarning

On 2.7.1 it works fine.

Seems to be adding warnings.simplefilter('always') call before deprecated_function() call fixes the issue:

import warnings

import pytest


def deprecated_function():
    warnings.warn("deprecated", DeprecationWarning)


def test_one():
    warnings.simplefilter('always')
    deprecated_function()


def test_two():
    pytest.deprecated_call(deprecated_function)

Could you please check this small issue?

[netme]

Also wanted to share an extended example:

import warnings

import pytest


def deprecated_function():
    warnings.warn("deprecated", DeprecationWarning)


def test_one():
    pass


def test_two():
    pytest.deprecated_call(deprecated_function)


def test_three():
    pytest.deprecated_call(deprecated_function)


def test_four():
    deprecated_function()


def test_five():
    pytest.deprecated_call(deprecated_function)

This example fails with the same error around test_five . test_two and test_three are passing.
Hope that can help.

[nicoddemus]

Thanks for the report @netme!

[nicoddemus]

Note: this fails only on Python 2.7.

[netme]

@nicoddemus Thanks for checking it. Yes, forgot to mention. Our product is using Python 2.7.8 .

[netme]

Temporary fixed it using

warnings.simplefilter('always', DeprecationWarning)

call close to our fixtures definition.

[nicoddemus]

Hmm that's strange. In #897 deprecated_call was refactored to use an internal RecordWarnings object which is very similar to the builtin warnings.catch_warnings, but which seems to have some special treatment regarding DeprecationWarning.

The following fails (note that pytest is not even involved):

import warnings

def deprecated_function():
    warnings.warn("deprecated", DeprecationWarning)

with warnings.catch_warnings(record=True) as ws:    
    deprecated_function()

assert len(ws) == 1

If you change deprecated_function to issue a UserWarning instead, then it works. I see this behavior both for Python 2.7 and 3.5. I would expect catch_warnings to capture all warnings, independently from any filters.

deprecated_call in 2.7 monkey-patched both warn and warn_explicit instead, that's why it worked on that version.

Anybody with more knowledge of the warnings module care to comment? @hunse perhaps?

[hunse]

DeprecationWarnings are not raised by Python with the default warning filter set (i.e. the default warning filter suppresses them). As @nicoddemus mentioned, the old deprecated_call monkey patched warn, so that's how it got around the filters.

I think the new behaviour makes sense, because ultimately, you want to test what the user will be seeing, right? If a user looks at your test, and sees that deprecated_function in the test is supposed to be raising a DeprecationWarning, and then runs deprecated_function herself and sees that there's no warning, she's going to wonder why there's a discrepancy. So I think the best thing to do is make sure the warning filters are set at the top of any test function or file testing DeprecationWarnings. One drawback to setting them in the test function is that it will leave them set for subsequent test function calls as well, which may be unexpected.

If we do decide to keep the new behaviour, we should definitely make sure it's documented in the changelog.

Alternatively, we can revert to the old behaviour. The way I would do this is by removing filters for DeprecationWarning at the beginning of deprecated_call, and then set the filters back to the old state at the end of the function.

[hunse]

For interest, here's the reasoning on why DeprecationWarnings are suppressed by default. It looks like unittest re-enables them; maybe pytest should do the same?

[RonnyPfannschmidt]

in my oppinion py.test should always reenable all warnings

@hpk42, @nicoddemus what do you think?

[nicoddemus]

Thanks a lot @hunse for the clear explanation. 😄

[nicoddemus]

@hunse

If a user looks at your test, and sees that deprecated_function in the test is supposed to be raising a DeprecationWarning...
Alternatively, we can revert to the old behaviour.

I think we should revert it: pytest.deprecated_call does not convey that a function is actually raising a warning, but that it has been deprecated (the fact that usually this is done by a warning is secondary I think). If it were named pytest.raises_deprecation_warning then I would agree with you. 😉

IMO keeping the current behavior would just lead to confusion, as users would see it fail all the time, unless they explicitly reset the filters themselves; seems like a poor user experience to me.

@RonnyPfannschmidt

in my oppinion py.test should always reenable all warnings

Personally I don't use warnings much so I don't have a strong opinion on this, but following what the unittest module does it makes sense to me for pytest to do the same, besides making porting unittest code more straightforward.

If we agree to this, I think we should re-enable all warnings by default in 2.9 only.

[nicoddemus]

Created a separate issue to discuss re-enabling all warnings. 😄

[RonnyPfannschmidt]

If @hpk42 agrees, I'd even go for it in the 2.8 series

[nicoddemus]

To re-enable all warnings? I'm not sure, seems like a big behavior change to me that should go into a minor release only, not in a bug fix release.

[RonnyPfannschmidt]

well, its a clear regression from 2.7 so i think a fix in 2.8.x is acceptable

[nicoddemus]

Oh I see what you mean. IMO we have two issues, which are related, but can be treated separately:

1. Change deprecated_call back to its 2.7.X implementation, so the user doesn't have to call warnings.simplefilter before every deprecated_call. This will fix this regression and I agree should go into 2.8.4.
2. Make pytest always re-enable all warnings. This potentially has other side effects in existing test suites (not sure how many or how bad really), but as this will happen by default I think this should go into 2.9 instead.

[RonnyPfannschmidt]

good thinking, lets fix 1 with this issue and have an extra issue for 2

[nicoddemus]

Agreed.

2 is already covered in #1191. 😄

[hunse]

Wait, this is nothing to do with DeprecationWarning. deprecated_call sets the warning filter to "always", so DeprecationWarning gets raised (this is how the old tests still pass). The reason @netme's script doesn't work is that test_one is called first, and raises the DeprecationWarning, and then it's not raised the second time in test_two, because Python has a thing that suppresses multiples of the same warning. The test works if you remove test_one. We should see how to make sure warnings are raised every time.

[hunse]

I have code in WarningsRecorder to do this, but for some reason it's not working. Also, the "always" filter in deprecated_call should be enough to do this. It might have something to do with the fact that the WarningsRecorder is being destroyed, but somehow it remembers that that warning has already been raised and suppresses it. I don't know...

EDIT: maybe because when the first warning is raised, none of the filters are set, so it gets added to some "ignore" list somewhere. Then, when the second warning is raised, the "always" filters are set, but it's already on that list, and gets ignored right away. I'm just guessing here. This needs more looking at, which unfortunately I don't have time for right now, but maybe I'll be able to get back to it tomorrow.

[nicoddemus]

The reason @netme's script doesn't work is that test_one is called first, and raises the DeprecationWarning, and then it's not raised the second time in test_two, because Python has a thing that suppresses multiples of the same warning.

I noticed that as well, forgot to mention it.

Perhaps there is some internal state of warnings module which is not being properly saved/restored by WarningsRecorder?

[netme]

@nicoddemus as far as I remember the problem is not around WarningRecorder.

If you look on my example, the WarningRecorder is not used around test_one, it's only used inside test_two. If it will help, I've also tried not to use pytest's recwarnextension and used warnings. catch_warnings(record=True). I had the similar issues.

Hope that will help you with debugging.

[nicoddemus]

I think I figured it out. warnings has a global registry per-module warnings which were already issued, and uses that to avoid exhibiting the same warning twice for the same module.

In this line you can see the registry being setup. If you look at up at that function, you can see that it tries to get the module to put the __warningregistry__ dict in a number of ways, but usually it is in the same module that called warns.

Then in this line we can see that it will just bail out and not issue a warning because the registry already contains an entry for DeprecationWarning at this point.

I don't think there's much we can do other than revert the implementation of deprecated_call back to its 2.7 version (another approach would be to try to mimic how warn obtains the __warningregistry__ dict and save/restore that, but I rather not go into that direction).

At least it is good to know what is actually happening here. 😅

I will prepare a PR restoring the deprecated_call implementation.