Kernel "Idle" Messages Arrive Before "Stream" Messages

[twavv]

I see that this has been discussed before, à la #238.

I was wondering what if this inconsistency with the Jupyter protocol will be fixed; the protocol specification says that "After processing the request and publishing associated IOPub messages, if any, the kernel publishes a status: idle message. This idle status message indicates that IOPub messages associated with a given request have all been received." (emphasis mine).

I discovered this while writing a kernel frontend and getting no responses to my println("foo") execution requests (the frontend in question considers requests to be done whenever the kernel replies with "idle"), and indeed, if you inspect the WebSocket communications on a normal notebook, you can see that the "status" message arrives before the "stream" message.

[stevengj]

Stream messages can take arbitrarily long to arrive after the cell executes. For example, a cell could consist of:

@async begin
   sleep(100)
   println("Done waiting.") # to stdout stream
   display("text/html", "<b>Really</b> done.") # sends display_data message
end

When you execute the cell, it launches an asynchronous task and sends kernel idle. The task sleeps in the background, and 100 seconds later it sends stream and display_data messages.

@Carreau, if the messaging spec requires that all IOPub messages be received upon an idle message, then maybe the messaging spec should be updated?

[twavv]

True, but the kernel specifications only concern synchronous code. Asynchronous code is purposefully left poorly defined. The same type of code is achievable in (eg) python, but synchronous code always has the "stream then status" behavior.

Would it be possible to just make sure that the stream buffers are empty before sending the idle message?

[stevengj]

We can and do call flush on the streams before sending the idle message, but that doesn't always flush buffers from e.g. external C or Fortran libraries, which may have buffers that are not under Julia's control.

(IPython doesn't capture I/O from external C libraries IIRC.)

[stevengj]

What OS are you on? @vtjnash commented that flushing reliably is especially hard on Windows.

[twavv]

Linux (Ubuntu 18.04).

The code in question is literally just a lone "println(...)"

[stevengj]

What happens if you add a couple of additional yield() calls here?

I wonder if it's just not waking up the correct task to read the streams? We need to do something more reliable than the current hack.

[Carreau]

Yes, there are some inconsistencies, and there are questions about asynchronous code we're unsure how to reply to.

There is some discussion about some docs update in jupyter/jupyter_client#388 maybe you could chime in there. I haven't touched the spec in a long time so Jason/Sylvain/Min may have better answer and idea on how this affect things.

[twavv]

@stevengj I added a whole bunch of println calls around the stdio.jl file to the original stdout (so that the text appears in the same console as where the notebook was started) and it seems that oslibuv_flush is never called at all.

I will admit to not completely understanding the way everything is architected and being not all that familiar with Julia but I think I found the culprit. flush_all is called before sending the idle message, and flush all calls flush(stdout).

IJulia.stdout = Base.PipeEndpoint(RawFD(41) open, 0 bytes waiting)

Base.STDOUT = IJulia.IJuliaStdio{Base.PipeEndpoint}(IOContext(Base.PipeEndpoint(RawFD(41) open, 0 bytes waiting)))
Sending stdout

So when flush(stdout) is called, it's using the IJulia.stdout which is I believe the original stdout, instead of the IJuliaStdio object, so the methods specific to the IJuliaStdio which do send the data in the streams over the Jupyter connection aren't evoked. I think this issue might have arisen as a result of the change from Base.STDOUT in Julia 0.6 to Base.stdout in Julia 0.7.

tldr: things worked in Julia 0.6 when I swapped flush(stdout) to flush(STDOUT). Things work already in Julia 0.7 beta.

I'd be happy to create a pull request that does something like sets jupyter_stdout and jupyter_stderr which always points to the IJuliaStdio (effectively, always to either Base.STDOUT or Base.stdout accordingly) and which changes flush_all to flush those buffers.

[twavv]

Ah, okay, I think I see.

redirect_stdout changes (using Julia 0.6) Base.STDOUT but not Compat.stdout.

STDOUT = IJulia.IJuliaStdio{Base.PipeEndpoint}(IOContext(Base.PipeEndpoint(RawFD(41) open, 0 bytes waiting)))
Base.STDOUT = IJulia.IJuliaStdio{Base.PipeEndpoint}(IOContext(Base.PipeEndpoint(RawFD(41) open, 0 bytes waiting)))

stdout = Base.PipeEndpoint(RawFD(41) open, 0 bytes waiting)
Compat.stdout = Base.PipeEndpoint(RawFD(41) open, 0 bytes waiting)

Various places around the IJulia codebase using stdout which is provided by Compat, so the solution seems to be to do the same monkeypatching of Compat as is done with Base.