Skip to content

Execute Requests Immediately Following and Error are Aborted in 5.5 #609

@MSeal

Description

@MSeal

In debugging nteract/testbook#88, which was traced to an issue in testbook behavior causing empty execute response messages with ipykernel 5.5 in several tests, I believe we have tacked down the change in behavior to this commit. It appears to have changed the error abort interaction such that any additional execute requests within stop_on_error_timeout after an error occurs are aborted.

The docs state Requests that arrive within this [stop_on_error_timeout] window after an error will be cancelled.. What was the intention for this feature and why did it change behavior in 5.5? The message sent are also odd if this was intentional behavior because there's no indicator in the execute_result that the intended execution was aborted. I feel an error message or status of sorts would be expected unless I am missing something here?

I believe this is unintended behavior, as 5.4.3 does not have this behavior and the 5.5.0 changelog has no mention of it. Additionally notebooks with allow-error flags could also hit this issue unexpectedly, depending on how the notebook executor was queuing / processing the requests. Testbook certainly hits this because it's often testing that something failed or trying optimistic execution paths. For now I think the only way around the issue is to wait after failed executions or set the stop_on_error_timeout to 0.

I've drafted the simplest example I could to demonstrate behavior with jupyter_client, please let me know if any additional details are needed / if this was intended and incidental behavior change:

In [1]: from jupyter_client.manager import start_new_kernel

In [2]: km, kc = start_new_kernel(kernel_name='python3')

# This is a dumbed down version of what nbclient does to poll until a cell has finished executing
In [3]: def poll_output_msg(parent_msg_id):
   ...:     msgs = []
   ...:     while True:
   ...:         msg = kc.iopub_channel.get_msg()
   ...:         if msg['parent_header'].get('msg_id') == parent_msg_id:
   ...:             msgs.append(msg)
   ...:         if msg['msg_type'] == 'status' and msg['content']['execution_state'] == 'idle':
   ...:             break
   ...:     return msgs
   ...: 

In [4]: def execute(req):
   ...:     return poll_output_msg(kc.execute(req))
   ...: 

# The first execution will result an a NameError, the second will not print post-error because it is executed immediately after
In [5]: a, b = execute("error_req"), execute("print('post-error')")

Here's the message contents showing the first cell a's error

In [6]: a
Out[6]: 
[{'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_4',
   'msg_type': 'status',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 518706, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_4',
  'msg_type': 'status',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_1',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 517670, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'execution_state': 'busy'},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_5',
   'msg_type': 'execute_input',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 518983, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_5',
  'msg_type': 'execute_input',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_1',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 517670, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'code': 'error_req', 'execution_count': 1},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_6',
   'msg_type': 'error',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 570318, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_6',
  'msg_type': 'error',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_1',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 517670, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'traceback': ['\x1b[0;31m---------------------------------------------------------------------------\x1b[0m',
    '\x1b[0;31mNameError\x1b[0m                                 Traceback (most recent call last)',
    '\x1b[0;32m<ipython-input-1-88f24347380f>\x1b[0m in \x1b[0;36m<module>\x1b[0;34m\x1b[0m\n\x1b[0;32m----> 1\x1b[0;31m \x1b[0merror_req\x1b[0m\x1b[0;34m\x1b[0m\x1b[0;34m\x1b[0m\x1b[0m\n\x1b[0m',
    "\x1b[0;31mNameError\x1b[0m: name 'error_req' is not defined"],
   'ename': 'NameError',
   'evalue': "name 'error_req' is not defined"},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_8',
   'msg_type': 'status',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 572037, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_8',
  'msg_type': 'status',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_1',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 517670, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'execution_state': 'idle'},
  'buffers': []}]

and here's cell b where no print message is made.

In [7]: b
Out[7]: 
[{'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_9',
   'msg_type': 'status',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 573157, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_9',
  'msg_type': 'status',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_2',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 572676, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'execution_state': 'busy'},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_11',
   'msg_type': 'status',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 573335, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_11',
  'msg_type': 'status',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_2',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 8, 31, 572676, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'execution_state': 'idle'},
  'buffers': []}]

If instead we add a sleep(0.2) between the execution requests, the print request correctly outputs a message:

In [12]: import time

In [13]: a, _, b = execute("error_req"), time.sleep(0.2), execute("print('post-error')")

In [14]: b
Out[14]: 
[{'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_27',
   'msg_type': 'status',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 303236, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_27',
  'msg_type': 'status',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_6',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 300607, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'execution_state': 'busy'},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_28',
   'msg_type': 'execute_input',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 303942, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_28',
  'msg_type': 'execute_input',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_6',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 300607, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'code': "print('post-error')", 'execution_count': 5},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_29',
   'msg_type': 'stream',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 307224, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_29',
  'msg_type': 'stream',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_6',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 300607, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'name': 'stdout', 'text': 'post-error\n'},
  'buffers': []},
 {'header': {'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_31',
   'msg_type': 'status',
   'username': 'mseal',
   'session': 'a6355c9a-25ad0390854e5e5912019c1e',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 309692, tzinfo=tzutc()),
   'version': '5.3'},
  'msg_id': 'a6355c9a-25ad0390854e5e5912019c1e_31',
  'msg_type': 'status',
  'parent_header': {'msg_id': 'df05c2aa-0ec98f3fa0453ce00aff4699_6',
   'msg_type': 'execute_request',
   'username': 'mseal',
   'session': 'df05c2aa-0ec98f3fa0453ce00aff4699',
   'date': datetime.datetime(2021, 3, 21, 22, 19, 2, 300607, tzinfo=tzutc()),
   'version': '5.3'},
  'metadata': {},
  'content': {'execution_state': 'idle'},
  'buffers': []}]

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions