bpo-32591: Add native coroutine origin tracking #5250

njsmith · 2018-01-20T08:57:25Z

After this PR, asyncio no longer uses sys.set_coroutine_wrapper.

There is one non-trivial semantic change: before in asycnio debug
mode, unawaited coroutine warnings were logged using
logger.error(...). Now they generate a regular warnings-module
warning.

This is best reviewed one commit at a time.

Note that there's also a fix for a very subtle bug in
BaseEventLoop.set_debug; see the 4th commit. (It's the one where the
commit message is 4x longer than the diff.)

Not done here, could be added here or in followups:

Support for enabling coroutine origin tracking via envvar or -X flag
Actually deprecating/removing sys.set_coroutine_wrapper

https://bugs.python.org/issue32591

This is fixing an old bug, that for some reason wasn't causing test suite failures until the previous commit. The issue was: Sometimes, for some reason, the tests are calling loop.set_debug() from a random thread, different from the one where the event loop is running. When set_debug() is called and the event loop is running, it attempts to immediately enable or disable debug stuff (previously registering/unregistering the coroutine wrapper, now toggling the coroutine origin tracking). However, it used to do this *in the thread where set_debug() was called*. Since the toggling uses a save/restore pattern, we'd end up saving the value in one thread and then restoring it in another, while never restoring it in the first thread, etc. Now we always enable/disable the debugging mode inside the event loop thread, which makes much more sense. And now the tests are passing again.

njsmith · 2018-01-20T09:01:12Z

Lib/warnings.py

+        msg_lines.append("Coroutine created at (most recent call last)\n")
+        msg_lines += traceback.format_list(list(extract()))
+    msg = "".join(msg_lines).rstrip("\n")
+    warn(msg, category=RuntimeWarning, stacklevel=2, source=coro)


Small, easy to miss point here: passing source=coro here means that if the user happens to have tracemalloc enabled, its origin traceback will be included in the warning. Kinda neat! It does mean if you have both set_coroutine_origin_tracking_depth and tracemalloc enabled you'll get two at-least-partially-redundant tracebacks in the same warning. I don't know that I care that much about this but FYI.

I think a redundant warning is OK. tracemalloc is enabled quite rarely. I also think what you wrote in this comment should be reflected in a code comment in case someone debugs the double warnings issue :)

1st1

Overall it looks good.

A couple more requests:

Let's raise a DeprecationWarning in sys.set_coroutine_wrapper. And we need to document that it has been deprecated and is scheduled to be removed in 3.8.
In what's new in 3.7, we need to add an entry about the deprecation of sys.set_coroutine_wrapper.
Minor nit: please fix C code style, mainly, add braces for single-statement "if" branches.

1st1 · 2018-01-20T15:23:42Z

Doc/library/sys.rst

+
+   Returns the old value of *depth*.
+
+   This setting is thread-local.


thread-local -> thread-specific

1st1 · 2018-01-20T15:25:14Z

Doc/library/inspect.rst

+|           | cr_origin         | where coroutine was       |
+|           |                   | created, if coroutine     |
+|           |                   | origin tracking is enabled|
+-----------+-------------------+---------------------------+


Can you add a link to the set_coroutine_origin_tracking_depth documentation snippet?

Well, that was my original thought. The problem is that

:func:`set_coroutine_origin_tracking_depth`

is too long to fit in the ascii-art box. So... either we need a shorter name for the function, or we need to redraw this whole giant table, and I couldn't think of a satisfactory way to do either in the 2 minutes I spent thinking about it :-). Any suggestions?

I guess we could use that weird ReST substitution thing? I'm not sure how that works.

Does this work: http://docutils.sourceforge.net/docs/user/rst/quickref.html#hyperlink-targets ?

1st1 · 2018-01-20T15:25:54Z

Doc/library/sys.rst

+   enabled, the ``cr_origin`` attribute on coroutine objects will
+   contain a list of (filename, line number, function name) tuples
+   describing the traceback where the coroutine object was created.
+   When disabled, ``cr_origin`` will be None.


Need to specify how the list is ordered.

1st1 · 2018-01-20T15:28:03Z

Include/warnings.h

@@ -56,6 +56,10 @@ PyErr_WarnExplicitFormat(PyObject *category,
 #define PyErr_Warn(category, msg) PyErr_WarnEx(category, msg, 1)
 #endif

+#ifndef Py_LIMITED_API
+PyAPI_FUNC(void) _PyErr_WarnUnawaitedCoroutine(PyObject *coro);


Strictly speaking we don't need PyAPI_FUNC here, as warnings.c|h will be linked with genobject.c and we are not going to use it in extensions.

1st1 · 2018-01-20T15:29:43Z

Lib/asyncio/base_events.py

-        enabled = bool(enabled)
-        if self._coroutine_wrapper_set == enabled:
+    def _set_coroutine_origin_tracking(self, enabled):
+        if enabled == self._coroutine_origin_tracking_enabled:


if enabled and self._coroutine_origin_tracking_enabled:?

I don't like using == for bools.

No, that would be different – the no-== equivalent would be:

if ((enabled and self._coroutine_origin_tracking_enabled) or (not enabled and not self._coroutine_origin_tracking_enabled)): ...

I find the == version easier to read. ("If the requested state equals the current state, return without doing anything.")

Got it, then I'd cast them both to bool: if bool(enabled) == bool(self._coroutine_origin_tracking_enabled):

1st1 · 2018-01-20T15:42:06Z

Objects/genobject.c

+
+    if (depth == 0) {
+        ((PyCoroObject *)coro)->cr_origin = NULL;
+    } else {


Again, per PEP 7:

if ( ... ) { } else { }

Also I'd like this whole else branch to be in a separate helper function.

1st1 · 2018-01-20T15:47:21Z

Objects/genobject.c

+    } else {
+        PyObject *origin = PyList_New(depth);
+        /* Immediately pass ownership to coro, so on error paths we don't have
+           to worry about it separately. */


The idea is neat, but it makes the code harder to read and it's not how we usually do it in CPython. While reviewing the code I've already added 2 comments asking you to add Py_DECREF(origin). Please do it the long way: create, populate, cleanup on errors, and finally assign it to cr_origin. After all it's just two places where an extra decref is needed.

1st1 · 2018-01-20T15:53:28Z

Objects/genobject.c

+            frame = frame->f_back;
+        }
+        /* Truncate the list if necessary */
+        if (PyList_SetSlice(origin, i, depth, NULL) < 0) {


Can we call PyList_SetSlice only when needed?

1st1 · 2018-01-20T15:57:44Z

Python/_warnings.c

+    */
+    fn = get_warnings_attr(&PyId__warn_unawaited_coroutine, 1);
+    if (fn) {
+        res = PyObject_CallFunctionObjArgs(fn, coro, NULL);


Just add Py_DECREF(fn) after this line.

1st1 · 2018-01-20T15:59:40Z

Python/ceval.c

+int
+_PyEval_SetCoroutineOriginTrackingDepth(int new_depth)
+{
+    PyThreadState *tstate = PyThreadState_GET();


Add assert(new_depth >= 0) for cases when somebody uses the C API directly (sys.set_coroutine_origin_tracking_depth has a check for Python users).

bedevere-bot · 2018-01-20T16:02:14Z

A Python core developer has requested some changes be made to your pull request before we can consider merging it. If you could please address their requests along with any other requests in other reviews from core developers that would be appreciated.

Once you have made the requested changes, please leave a comment on this pull request containing the phrase I have made the requested changes; please review again. I will then notify any core developers who have left a review that you're ready for them to take another look at this pull request.

1st1 · 2018-01-21T01:41:20Z

Objects/genobject.c

+        PyObject *origin = PyList_New(depth);
+        /* Immediately pass ownership to coro, so on error paths we don't have
+           to worry about it separately. */
+        ((PyCoroObject *)coro)->cr_origin = origin;


I just realized that exposing list object directly through cr_origin means that users can mutate it. How about we cycle through the frames two times: 1st time to determine the real depth we can capture; 2nd time to populate a cr_origin tuple (not list). Traversing a relatively short chain of frames should be pretty fast, and this is a debug mode after all. What do you think?

Another option would be to keep things as is, but to change cr_origin to a getter, and return a copy of the list every time. But I like the tuple idea more.

Right, I originally left out the Py_VISIT call and then realized that mutation was possible, so figured I'd put it in just in case :-).

I don't think it matters too much whether we expose a tuple, copy the list, or just keep the current thing where someone can mutate it if they really want to. (The warnings code is robust against such shenanigans: worst case it'll print an error b/c cr_origin was corrupt, and then the real warning without a traceback.) Given this I have a mild preference not to do the tuple thing, because it leads to the most complicated C code. Doing an extra loop is totally doable of course, but it's also plenty complicated to hide some kind of off-by-one bug or something.

1st1 · 2018-01-21T01:44:06Z

Python/sysmodule.c

@@ -1512,6 +1542,7 @@ static PyMethodDef sys_methods[] = {
    {"call_tracing", sys_call_tracing, METH_VARARGS, call_tracing_doc},
    {"_debugmallocstats", sys_debugmallocstats, METH_NOARGS,
     debugmallocstats_doc},
+    SYS_SET_COROUTINE_ORIGIN_TRACKING_DEPTH_METHODDEF


Add sys.get_coroutine_origin_tracking_depth?

Eh, I guess. I was thinking this is sufficiently arcane functionality that I could be lazy and get away with the set-returns-the-old-value pattern (cf. signal.set_wakeup_fd), but you're probably right that set+get is a nicer API.

njsmith · 2018-01-21T05:19:19Z

This worked: http://www.sphinx-doc.org/en/stable/rest.html#substitutions

…

On Sat, Jan 20, 2018 at 8:51 PM, Yury Selivanov ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In Doc/library/inspect.rst <#5250 (comment)>: > @@ -215,6 +215,10 @@ attributes: +-----------+-------------------+---------------------------+ | | cr_code | code | +-----------+-------------------+---------------------------+ +| | cr_origin | where coroutine was | +| | | created, if coroutine | +| | | origin tracking is enabled| ++-----------+-------------------+---------------------------+ Does this work: http://docutils.sourceforge.net/docs/user/rst/quickref. html#hyperlink-targets ? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5250 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAlOaO4NcvwZwIJbftzlLOSgyObtU2imks5tMsJXgaJpZM4RlXZz> .

-- Nathaniel J. Smith -- https://vorpus.org <http://vorpus.org>

njsmith · 2018-01-21T05:20:46Z

Okay, I think that last push addresses everything except:

Py_VISIT vs tuples vs copying lists
set vs set+get

1st1 · 2018-01-21T05:34:41Z

I still don't like the idea of returning the original mutable list :( Let's do some extra work and make this list a tuple of tuples. It's better than have a getter for cr_origin+copy.

And let's have a 'get' method, otherwise it's hard to capture the current sys settings for debug purposes or whatnot.

njsmith · 2018-01-21T05:40:22Z

I'm not a huge fan b/c tuples shouldn't be used for homogenous variable-length sequences, but... fine

njsmith · 2018-01-21T05:40:58Z

I have made the requested changes; please review again

bedevere-bot · 2018-01-21T05:41:00Z

Thanks for making the requested changes!

@1st1: please review the changes made to this pull request.

1st1 · 2018-01-21T05:48:42Z

I'm not a huge fan b/c tuples shouldn't be used for homogenous variable-length sequences, but... fine

Yeah, I know, but we don't have a frozenlist.

…5250

…5291)

njsmith added 6 commits January 19, 2018 23:39

Add coro.cr_origin and sys.set_coroutine_origin_tracking_depth

091dc24

Use coroutine origin information in the unawaited coroutine warning

d504810

Stop using set_coroutine_wrapper in asyncio debug mode

5d8f591

Add NEWS blurb

6c7f73a

Guess I should add myself to ACKS at some point

7738cc4

njsmith requested review from 1st1 and asvetlov as code owners January 20, 2018 08:57

the-knights-who-say-ni added the CLA signed label Jan 20, 2018

bedevere-bot added the awaiting review label Jan 20, 2018

njsmith commented Jan 20, 2018

View reviewed changes

1st1 requested changes Jan 20, 2018

View reviewed changes

bedevere-bot added awaiting changes and removed awaiting review labels Jan 20, 2018

1st1 reviewed Jan 21, 2018

View reviewed changes

Address most of Yury's comments

2157af3

njsmith added 2 commits January 20, 2018 21:34

Switch coroutine origin tracking to a get/set API

b0e52ec

Make cr_origin a tuple

c0feb3b

bedevere-bot added awaiting change review and removed awaiting changes labels Jan 21, 2018

1st1 approved these changes Jan 21, 2018

View reviewed changes

bedevere-bot added awaiting merge and removed awaiting change review labels Jan 21, 2018

1st1 merged commit fc2f407 into python:master Jan 21, 2018

bedevere-bot removed the awaiting merge label Jan 21, 2018

njsmith added a commit to njsmith/cpython that referenced this pull request Jan 24, 2018

bpo-32636: Fix @asyncio.coroutine debug mode bug exposed by pythongh-…

98d6095

…5250

1st1 pushed a commit that referenced this pull request Jan 24, 2018

bpo-32636: Fix @asyncio.coroutine debug mode bug exposed by gh-5250 (#…

fb5a7ad

…5291)

wallies mentioned this pull request Mar 4, 2018

AttributeError: module 'asyncio.coroutines' has no attribute 'debug_wrapper' MagicStack/uvloop#126

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

bpo-32591: Add native coroutine origin tracking #5250

bpo-32591: Add native coroutine origin tracking #5250

njsmith commented Jan 20, 2018 •

edited by bedevere-bot

Loading

njsmith Jan 20, 2018

1st1 Jan 20, 2018 •

edited

Loading

1st1 left a comment

1st1 Jan 20, 2018

1st1 Jan 20, 2018

njsmith Jan 21, 2018

1st1 Jan 21, 2018

1st1 Jan 20, 2018

1st1 Jan 20, 2018 •

edited

Loading

1st1 Jan 20, 2018 •

edited

Loading

njsmith Jan 21, 2018

1st1 Jan 21, 2018

1st1 Jan 20, 2018

1st1 Jan 20, 2018

1st1 Jan 20, 2018

1st1 Jan 20, 2018

1st1 Jan 20, 2018

1st1 Jan 20, 2018

bedevere-bot commented Jan 20, 2018

1st1 Jan 21, 2018

1st1 Jan 21, 2018

njsmith Jan 21, 2018

1st1 Jan 21, 2018

njsmith Jan 21, 2018

njsmith commented Jan 21, 2018 via email

njsmith commented Jan 21, 2018

1st1 commented Jan 21, 2018

njsmith commented Jan 21, 2018

njsmith commented Jan 21, 2018

bedevere-bot commented Jan 21, 2018

1st1 commented Jan 21, 2018


		Returns the old value of depth.

		This setting is thread-local.

bpo-32591: Add native coroutine origin tracking #5250

bpo-32591: Add native coroutine origin tracking #5250

Conversation

njsmith commented Jan 20, 2018 • edited by bedevere-bot Loading

Choose a reason for hiding this comment

1st1 Jan 20, 2018 • edited Loading

Choose a reason for hiding this comment

1st1 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

1st1 Jan 20, 2018 • edited Loading

Choose a reason for hiding this comment

1st1 Jan 20, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bedevere-bot commented Jan 20, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

njsmith commented Jan 21, 2018 via email

njsmith commented Jan 21, 2018

1st1 commented Jan 21, 2018

njsmith commented Jan 21, 2018

njsmith commented Jan 21, 2018

bedevere-bot commented Jan 21, 2018

1st1 commented Jan 21, 2018

njsmith commented Jan 20, 2018 •

edited by bedevere-bot

Loading

1st1 Jan 20, 2018 •

edited

Loading

1st1 Jan 20, 2018 •

edited

Loading

1st1 Jan 20, 2018 •

edited

Loading