classification
Title: Different error message when sys.settrace is used
Type: Stage: resolved
Components: Interpreter Core Versions: Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: SylvainDe, inada.naoki, serhiy.storchaka, steven.daprano, xtreak, yselivanov
Priority: normal Keywords: patch

Created on 2019-02-18 18:06 by SylvainDe, last changed 2019-04-01 08:57 by inada.naoki. This issue is now closed.

Files
File name Uploaded Description Edit
issue36_git_bisect_script_and_results.txt SylvainDe, 2019-02-18 18:06
Pull Requests
URL Status Linked Edit
PR 11930 merged inada.naoki, 2019-02-19 09:29
Messages (12)
msg335857 - (view) Author: SylvainDe (SylvainDe) * Date: 2019-02-18 18:06
Context:
--------
Follow-up from https://bugs.python.org/issue35965 which was closed when we assumed the issue was on the coverage side.
After nedbat investigation, it seems like the issue comes from call to "sys.settrace".



Issue:
------
A test relying on "self.assertRaisesRegex" with raising code "set.add(0)" started to lead to a different error message recently on the CI jobs.

Indeed, instead of 
   "descriptor '\w+' requires a 'set' object but received a 'int'"
the raised exception was:
    "descriptor 'add' for 'set' objects doesn't apply to 'int' object"


More surprisingly, the behavior was different:
 - depending on whether "self.assertRaisesRegex" was used as a context manager
 - on the Python version
 - when coverage was used. Nedbat was able to pinpoint the root cause for this: the usage of "sys.settrace".


This can be hilighted using simple unit-tests:

======================================================================================================
    import unittest
    import sys
    
    
    def trace(frame, event, arg):
        return trace
    
    
    DESCRIPT_REQUIRES_TYPE_RE = r"descriptor '\w+' requires a 'set' object but received a 'int'"
    DO_SET_TRACE = True
    
    class SetAddIntRegexpTests(unittest.TestCase):
    
        def test_assertRaisesRegex(self):
            if DO_SET_TRACE:
                sys.settrace(trace)
            self.assertRaisesRegex(TypeError, DESCRIPT_REQUIRES_TYPE_RE, set.add, 0)
    
        def test_assertRaisesRegex_contextman(self):
            if DO_SET_TRACE:
                sys.settrace(trace)
            with self.assertRaisesRegex(TypeError, DESCRIPT_REQUIRES_TYPE_RE):
                set.add(0)
    
    if __name__ == '__main__':
        unittest.main()
======================================================================================================


Here are the results from the original bug:

    On some versions, both tests pass:
        Python 3.6 and before
        Python 3.7.0a4+ (heads/master:4666ec5, Jan 26 2018, 04:14:24) - [GCC 4.8.4] - ('CPython', 'heads/master', '4666ec5'))

    On some versions, only test_assertRaisesRegex_contextman fails which was the confusing part:
        Python 3.7.1 (default, Dec 5 2018, 18:09:53) [GCC 5.4.0 20160609] - ('CPython', '', '')
        Python 3.7.2+ (heads/3.7:3fcfef3, Feb 9 2019, 07:30:09) [GCC 5.4.0 20160609] - ('CPython', 'heads/3.7', '3fcfef3')

    On some versions, both tests fail:
        Python 3.8.0a1+ (heads/master:8a03ff2, Feb 9 2019, 07:30:26) [GCC 5.4.0 20160609] - ('CPython', 'heads/master', '8a03ff2')




First analysis:
---------------
Using some git bisect magic, I was able to pinpoint the commits leading to each behavior change.

 - test_assertRaisesRegex_contextman starts to fail from: https://bugs.python.org/issue34126 https://github.com/python/cpython/commit/56868f940e0cc0b35d33c0070107ff3bed2d8766
 - test_assertRaisesRegex starts to fail as well from: https://bugs.python.org/issue34125 https://github.com/python/cpython/commit/e89de7398718f6e68848b6340830aeb90b7d582c


From my point of view, it looks like we have 2 regressions. Please let me know if this needs to be split into 2 independant issues.
msg335873 - (view) Author: Steven D'Aprano (steven.daprano) * (Python committer) Date: 2019-02-18 23:13
Do I correctly understand the reported problem here?

set.add(0) correctly raises TypeError in each case, but:

(1) the exception message changes between versions;

(2) and also changes depending on whether or not sys.trace is active.

I don't think the exception message (as opposed to the exception type) is part of the public API. This means it can change without warning, at any time, so long as it is sensible and human readable.

Unless there is something documenting the precise wording used in this case, guaranteeing that it will be kept stable, I don't think this should be considered a regression or a bug. Do you disagree?
msg335875 - (view) Author: SylvainDe (SylvainDe) * Date: 2019-02-18 23:32
This is mostly true and I agree that error messages are not part of the API.

However, I'd like to add the following points:
 - the error message was more meaningful before
 - the fact that having system.settrace used or not changes the behaviour makes me think this is not intentional.
 - the fact that the behaviour for unit test.assertRaisesRegexp is different depending on whether it is used as a context manager makes me think this is not intentional. From the documentation it seems like the 2 should behave the same way.

Thus, even if this eventually deserves to be closed as a non-issue, I'd rather go on the safe side and double check if this is the desirable behaviour or if something went wrong with the commits previously mentioned. Maybe Jeroen Demeyer (jdemeyer) would have more hindsight about this.

Does that look like an acceptable trade off?
msg335896 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-02-19 07:43
Looks this is due to the method calls optimization (issue26110). We now avoid to create a temporary bound method, and an error with different message is raised on this path.

>>> set.add(0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: descriptor 'add' requires a 'set' object but received a 'int'
>>> set.add.__get__(0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: descriptor 'add' for 'set' objects doesn't apply to 'int' object
msg335903 - (view) Author: Inada Naoki (inada.naoki) * (Python committer) Date: 2019-02-19 08:36
> Thus, even if this eventually deserves to be closed as a non-issue, I'd rather go on the safe side and double check if this is the desirable behaviour or if something went wrong with the commits previously mentioned. 

As Serhiy mentioned, this error message is raised from optimization path.
Nothing went wrong.  Error messages are vary depending on internal C code paths.  So this is not an bug or issue.  People must not rely on error message.

On the other hand, I don't oppose to making error messages more consistent.
It improve code health, like fixing typos in C comment which Python user doesn't see.
msg335904 - (view) Author: SylvainDe (SylvainDe) * Date: 2019-02-19 08:40
Thanks for the investigation. I'm fine with the explanation provided.
msg335911 - (view) Author: Inada Naoki (inada.naoki) * (Python committer) Date: 2019-02-19 09:26
Is this make sense?

>>> set.add(0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: descriptor 'add' for type 'set' doesn't apply to type 'int'
>>> set.add.__get__(0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: descriptor 'add' for type 'set' doesn't apply to type 'int'
msg335913 - (view) Author: SylvainDe (SylvainDe) * Date: 2019-02-19 09:34
This looks good to me :)
msg335914 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-02-19 09:41
I consider this as a minor regression in 3.7, unless there were reasons to change error messages. I think that in this case the change that restores error messages should be backported to 3.7.
msg335918 - (view) Author: Inada Naoki (inada.naoki) * (Python committer) Date: 2019-02-19 10:11
@Serhiy Error messages are not changed in 3.7.  They are different from 3.6.
Optimization in 3.7 changed "code path", not error message.
So it's difficult to fix this without breaking existing behavior.

Python 3.6.7 (default, Dec 18 2018, 17:32:18)
[GCC 4.2.1 Compatible Apple LLVM 9.0.0 (clang-900.0.39.2)] on darwin
>>> set.add(0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: descriptor 'add' requires a 'set' object but received a 'int'
>>> set.add.__get__(0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: descriptor 'add' for 'set' objects doesn't apply to 'int' object
msg335919 - (view) Author: Inada Naoki (inada.naoki) * (Python committer) Date: 2019-02-19 10:24
BTW, should we have different error message for class methods and instance mehtods?

* method: "descriptor 'X' for 'Y' objects doesn't apply to a 'Z' object"
* classmethod: "descriptor 'X' for 'Y' types doesn't apply to a 'Z' type"

Currently, classmethod notice about subtype, but instance method doesn't notice about subtype.
Should we notice about subtype in both error message?
Could someone write short, clear, and consistent error message?
msg339286 - (view) Author: Inada Naoki (inada.naoki) * (Python committer) Date: 2019-04-01 08:56
New changeset 62f9588663ebfea1735e9d142ef527395a6c2b95 by Inada Naoki in branch 'master':
bpo-36026: make descr error message consistent (GH-11930)
https://github.com/python/cpython/commit/62f9588663ebfea1735e9d142ef527395a6c2b95
History
Date User Action Args
2019-04-01 08:57:04inada.naokisetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2019-04-01 08:56:23inada.naokisetmessages: + msg339286
2019-02-19 11:26:25vstinnersetnosy: - vstinner
2019-02-19 10:24:08inada.naokisetmessages: + msg335919
2019-02-19 10:11:15inada.naokisetmessages: + msg335918
2019-02-19 09:41:03serhiy.storchakasetmessages: + msg335914
2019-02-19 09:34:26SylvainDesetmessages: + msg335913
2019-02-19 09:29:24inada.naokisetkeywords: + patch
stage: patch review
pull_requests: + pull_request11954
2019-02-19 09:26:58inada.naokisetmessages: + msg335911
2019-02-19 08:40:08SylvainDesetmessages: + msg335904
2019-02-19 08:36:33inada.naokisetversions: - Python 3.7
title: Different error message when sys.settrace is used (regressions) -> Different error message when sys.settrace is used
messages: + msg335903

components: + Interpreter Core
type: behavior ->
2019-02-19 08:27:37SylvainDesettype: behavior
versions: + Python 3.7, Python 3.8
2019-02-19 07:43:12serhiy.storchakasetnosy: + inada.naoki, yselivanov
messages: + msg335896
2019-02-18 23:32:02SylvainDesetmessages: + msg335875
2019-02-18 23:13:26steven.dapranosetnosy: + steven.daprano
messages: + msg335873
2019-02-18 18:11:30xtreaksetnosy: + vstinner, serhiy.storchaka
2019-02-18 18:10:02xtreaksetnosy: + xtreak
2019-02-18 18:06:04SylvainDecreate