Change in behavior when overriding warnings.showwarning and with catch_warnings(record=True)

[ThomasRobitaille]

BPO	28835
Nosy	@brettcannon, @ncoghlan, @vstinner, @ned-deily, @vadmium, @serhiy-storchaka, @JulienPalard
PRs	[Do Not Merge] Convert Misc/NEWS so that it is managed by towncrier #552
Files	warnings_fix.patch warnings_fix-2.patch warnings_fix-3.patch showwarning-tidy.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vstinner'
closed_at = <Date 2016-12-06.22:16:58.728>
created_at = <Date 2016-11-30.00:29:27.929>
labels = ['type-bug', '3.7']
title = 'Change in behavior when overriding warnings.showwarning and with catch_warnings(record=True)'
updated_at = <Date 2017-03-31.16:36:16.924>
user = 'https://bugs.python.org/ThomasRobitaille'

bugs.python.org fields:

activity = <Date 2017-03-31.16:36:16.924>
actor = 'dstufft'
assignee = 'vstinner'
closed = True
closed_date = <Date 2016-12-06.22:16:58.728>
closer = 'ned.deily'
components = []
creation = <Date 2016-11-30.00:29:27.929>
creator = 'Thomas.Robitaille'
dependencies = []
files = ['45767', '45768', '45769', '45775']
hgrepos = []
issue_num = 28835
keywords = ['patch']
message_count = 24.0
messages = ['282056', '282184', '282458', '282476', '282477', '282480', '282483', '282484', '282491', '282492', '282493', '282509', '282512', '282513', '282515', '282516', '282563', '282570', '282571', '282646', '282657', '282725', '282734', '282758']
nosy_count = 9.0
nosy_names = ['brett.cannon', 'ncoghlan', 'vstinner', 'ned.deily', 'python-dev', 'martin.panter', 'serhiy.storchaka', 'Thomas.Robitaille', 'mdk']
pr_nums = ['552']
priority = None
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue28835'
versions = ['Python 3.6', 'Python 3.7']

[ThomasRobitaille]

In Python 3.5, the following code:

    import warnings

    def deal_with_warning(*args, **kwargs):
        print("warning emitted")

    with warnings.catch_warnings(record=True):
        warnings.showwarning = deal_with_warning
        warnings.warn("This is a warning")

results in "warning emitted" being printed to the terminal.

In Python 3.6 however (at least in 3.6b1), nothing is printed, meaning that deal_with_warning is not getting called. I bisected the CPython history and tracked it down to the changes in this issue:

https://bugs.python.org/issue26568

However it doesn't look like this was an intentional change in behavior, since it says in the description of that issue:

"For backward compatibility, warnings.showmsg() calls warnings.showwarning() if warnings.showwarning() was replaced. Same for warnings.formatmsg(): call warnings.formatwarning() if replaced."

So I believe this is a bug? (since backward-compatibility is not preserved). If not, should the change in behavior be mentioned in the changelog?

[vstinner]

It seems like a regression of Python 3.6, probably introduced by myself with add addition of warnings._showwarningmsg() and the source parameter.

[ned-deily]

What's the status of this issue? It's currently blocking 360rc1. We either need a resolution now or defer it to 3.6.1.

[vstinner]

Ok, here is a fix.

[vstinner]

Oops, I made a mistake just before producing the patch: here is the right patch, test_warnings pass.

[vstinner]

Serhiy: Would you mind to review warnings_fix-2.patch? I tagged this bug as a release blocker, since it's a regression introduced in 3.6.

[JulienPalard]

Carefully reviewed, and tests are passing, issue is fixed: LGTM.

[vstinner]

Patch version 3: fix test_warnings when running the test with python3 -Werror. Reset filters in the new unit test.

[ncoghlan]

+1 from me as well

[vadmium]

The patch looks sensible to me. The fix is basically an extension to the first fixup (9c92352324e8), where Victor split _showwarnmsg_impl() out of _showwarnmsg(). Now, _showwarnmsg() is a helper for the C module to choose between the backwards-compatible showwarning() API, and the new internal _showwarnmsg_impl() function.

I left some incidental comments on Rietveld, but they are not severe release blockers. Also, is the docstring for warnings._showwarnmsg() off? It looks like you copied it from warnings.showwarning(). Best not to suggest replacing an internal function.

[vadmium]

Actually, I found a regression. Looks like you also need to cancel any showwarning() function set by the user:

>>> import warnings
>>> warnings.showwarning = print
>>> with warnings.catch_warnings(record=True) as recording:
...     warnings.warn("hi")  # Unpatched did not call print()
... 
hi <class 'UserWarning'> __main__ 2 None None
>>> recording  # Unpatched returned the warning here
[]

Also, should the documentation of catch_warnings() be amended to say that there is no longer a custom showwarning() function? The recording mechanism is now an internal detail, and not accessible by calling showwarning().

[serhiy-storchaka]

I don't understand why test_showwarnmsg_missing was added. Why deleting warnings._showwarnmsg should be supported?

I would rename _showwarning to _showwarning_orig for accenting it's purpose. It is used only for checking if showwarning was replaced by the user.

[python-dev]

New changeset 150d36dbe3ba by Victor Stinner in branch '3.6':
warnings: Fix the issue number
https://hg.python.org/cpython/rev/150d36dbe3ba

[vstinner]

I pushed a more complete version of my patch:

New changeset 726308cfe3b5 by Victor Stinner in branch '3.6':
catch_warnings() calls showwarning() if overriden
https://hg.python.org/cpython/rev/726308cfe3b5

I dislike pushing a different change than the reviewed change, but I was in a hurry for the Python 3.6.0 release :-/ Sorry about that.

Please double-check the pushed change!

(I used the wrong issue number, fixed in the following commit.)

The final change also fixes the bug reported by Martin:

Martin: "Actually, I found a regression. Looks like you also need to cancel any showwarning() function set by the user:"

I fixed it in catch_warnings() with these lines:

            # Reset showwarning() to the default implementation to make sure
            # that _showwarnmsg() calls _showwarnmsg_impl()
            self._module.showwarning = self._module._showwarning

It also added a new unit test for this scenario.

Serhiy Storchaka: "I don't understand why test_showwarnmsg_missing was added. Why deleting warnings._showwarnmsg should be supported?"

I don't know well the warnings module. The interactions between the C _warnings module and the Python warnings module are complex. I didn't want to break the backward compatibility, and *technically*, it is possible to delete warnings.showwarning() and warnings.warn("msg") still writes the message into stderr! So I decided to support this corner case, for the backward compatibility.

Code:
---

import warnings
warnings.warn("with showwarning")
del warnings.showwarning
warnings.warn("without showwarning")

---

Output on Python 3.5 (before my showarnmsg() changes):
---
x.py:2: UserWarning: with showwarning
warnings.warn("with showwarning")
x.py:4: UserWarning: without showwarning
warnings.warn("without showwarning")
---

Hum, but maybe we should decorate test_showwarnmsg_missing() with @cpython_only to announce that it's a side effect of the implementation, it's not part of the "Python specification".

Serhiy Storchaka: "I would rename _showwarning to _showwarning_orig for accenting it's purpose. It is used only for checking if showwarning was replaced by the user."

Sorry, I suck at naming things :-) Feel free to rename it (after the 3.6.0 release).

By the way, I'm still interested to make showwarnmsg() public in Python 3.7. IMO it's interesting to give access to the new source parameter to custom warning loggers. And it will allow to more easily extend warnings with new parameters (it was the whole purpose of the issue bpo-26568).

I keep the issue open so someone can still review the pushed change.

[vstinner]

Julien reviewed the pushed change and asked me questions on IRC:

• "nonlocal log": this change is unrelated to the fix, I should have done that in a separated change, sorry, I cannot resist to refactoring :-) The change has no effect, it's more cosmetic to help reviewers: "log is not a local variable nor a global variable, it's a "non-local" variable".

• inner function (calling log.append) renamed from "showarnmsg()" to "showarnmsg_logger()": it's to help debugging. It's a pain when two different functions completely different have the same name, especially for the warnings where many functions are overriden at runtime. Moreover, the function is now used for _showwarnmsg_impl instead of _showwarnmsg, so I also renamed the function to avoid confusion.

[serhiy-storchaka]

Here is a patch that cleans up the code.

[brettcannon]

Serhiy's patch LGTM.

[python-dev]

New changeset aaee06743c61 by Ned Deily in branch '3.6':
Issue bpo-28835: Tidy previous showwarning changes based on review comments.
https://hg.python.org/cpython/rev/aaee06743c61

New changeset 7bca3bf6401a by Ned Deily in branch 'default':
Issue bpo-28835: merge from 3.6
https://hg.python.org/cpython/rev/7bca3bf6401a

[ned-deily]

Thanks everyone for getting this resolved for 360rc1!

[brettcannon]

There's also issue bpo-28835 which might be related.

[ned-deily]

Brett, msg282646 ?

[brettcannon]

I just happened to look at that bug before seeing this bug and both mentioned recording issues so I thought I would mention there was a chance of a connection.

[vadmium]

Brett, what was the other bug? The bug number you posted is for this bug.

[ncoghlan]

If the intended reference was to bpo-28897, then yes, it was related: NumPy had introduced a workaround for the regression that existed in the beta releases (presumably thinking it was an intentional change that just hadn't been added to the porting guide yet), and this fix for the regression broke their workaround.

Reverting the workaround on the NumPy side restored compatibility :)