Intermittent problem with print output in Qt console.

[takluyver]

With trunk today, sometimes, a print statement at the Qt console can leave its output after the next input prompt. A bit like this:

In [5]: print a
12

In [6]: print a

In [7]: 12

Over a few runs, this happened on the 1st, 4th, 6th, 10th try (just using the up key to get the same command from history). There was no error message at the console. After it has happened, the cursor is on the next line, and input can continue (the console considers it multiline input).

[ellisonbg]

This is a known issue related to the asynchronous nature of how stdout is brought back to the frontend. Basically, there is no way for the frontend to know if/when stdout will arrive. Ideally, stdout is fast, so it gets back before the frontend moves on. The difficulty with our current design is that the frontend is on big textarea, so it is quite difficult to place the "12" back where is should go. to fix this, we will need to create subwidgets for each In/Out. That will enable us to use the information that comes back with each stdout to place the output with the associated In.

[takluyver]

Without knowing precisely how it works, would it not make sense to, when stdout arrives, cut the prompt and any fresh input to a temporary buffer, print from stdout, then stick the prompt+input back on the end? Or keep a note of the end of the output from each command, and insert text there (I know that's possible in Tkinter, so I imagine there's some equivalent in Qt).

[ellisonbg]

I think this type of logic is possible, although I seem to recall that Evan said it was a bit complicated. But this is definitely worth looking at.

[takluyver]

It kind of depends on what's going to happen with the Qt console. If it's a technology demonstrator, then this just demonstrates that there are better ways to do it. If it's intended as a base to build on, it depends how people decide to build on it. If it's to be shipped as a frontend itself, we'll need to sort this out one way or another.

[fperez]

I've also wondered if it wouldn't be a bad idea to add, right as we're about to print the next input prompt, a

time.sleep(0.1)
flush_stdout()

I'm fully aware that this is nothing but a hack, and that the real issue is the asynchronous situation Brian details above. But I wonder if something like this wouldn't at least catch most of the common cases, leaving the odd interleaving problems to happen only when there's genuinely delayed output (rather than just a race between stdout and the next prompt on every input).

[ellisonbg]

I thought we had already added something like that...

[fperez]

I don't think so, at least I don't see it. The code that shows the prompt is this one:

https://github.com/ipython/ipython/blob/master/IPython/frontend/qt/console/console_widget.py#L1807

and it doesn't seem to do any flushing. But given the signal/slot architecture in Qt, it's possible that machinery is there, in a different location, and I'm missing something.

[ellisonbg]

But, we have time.sleep's all over this code now and I have a feeling that they are all somewhat sensitive to the timing of everything. I would not be surprised at all if one of our time.sleeps affects this issue. But, this is part of what I don't like about time.sleeps: it is really difficult to understand why they are there months later.

[fperez]

Very true... The joys of async code :)

Now that Evan is around more, perhaps we could do an audit of all of this at least in the Qt code, and think about how to use (if at all) sleeps in a single location and in a way that we control a bit more.

[epatters]

Ah, the old issue...

As a data point, I should add that this seems to be happening more frequently now than I recall. In particular, it was happening a ton on my Windows machine yesterday.

But in any case, as Thomas suggests and as Brian advocated long ago, I think we will have to handle the 'bad' case and perform the insertion in the correct spot. This is doable, but highly non-trivial due to the lack of structure in the text document. Otherwise, even with sleeps, it will always be a bit fragile, which is not acceptable for a production-ready widget.

I will be working on this over the coming weeks.

[ellisonbg]

Evan, is it possible to add some sort of marker in the document at the proper place where future output would be written. If an in-document marker doesn't work, then maybe a structure that keeps pointers to the right place in the document would work. Then you could use that marker/pointer to quickly find the right place later on.

[epatters]

I will have to re-visit Qt documentation, but something like this will work. We need to store a reference to the appropriate QTextBlock. It's basically what I did to permit the replacement of the old prompts when the prompt number is wrong. I suppose it's not that bad; it just makes an already complicated widget more complicated :)

[fperez]

I have no idea why, but I also see it much more often now. It used to be a rare occurrence, now it's frequent enough to be really annoying. But I have no clue what may be causing it to be so frequent.

[epatters]

So I am not imagining things then. I still think we should fix this "properly", but it would be good to know what has made it worse lately.

[fperez]

No, it's not your imagination. Though I'm really baffled as well. I wonder if recent improvements to zmq have changed things, it could even be that an improvement to zmq has changed its timing patterns, making this problem more likely on our end.

[minrk]

Can I ask what version of zeromq/pyzmq everyone is using, and on what platform? I can't seem to reproduce this on purpose right now, though I have definitely seen it many times in the past. I'm on zeromq/pyzmq 2.1.1 (current master of both) on OSX-10.6.

As Evan pointed out, cell-like (linking in/out) behavior in a decidedly non-cell environment makes for complicated code, especially when one side is asynchronous, and can be in the form of zero-to-many messages (even one-to-many would be much easier).

I should note that I can cause this kind of issue in any terminal application with asynchronous events. Granted, 'print 12' is pretty reliable, but anything with threads (like ipython -pylab), I can get messages showing up in my prompt. This is a fundamental problem of a terminal-style frontend working with asynchronous events that have output.

It is certainly possible and desirable for Evan to wrestle this into better behavior here for simple cases, but we shouldn't expect perfect cell behavior and terminal style at the same time if we want the code to be clean.

A notebook-style design with linked input and output fields would cleanly resolve the problem, but is another project altogether.

[epatters]

The two systems on which I have noticed the increased frequency of delayed stdout are:

1. My Windows 7 desktop. This is using (Py)ZMQ 2.0.10 from EPD 7.0.
2. My Ubuntu VM. (Do not recall (Py)ZMQ version, probably 2.0.10)

On MacBook Pro (also using (Py)ZMQ 2.0.10), things are quite solid. I was trying just now to make this happen, and I couldn't.

[fperez]

I'm on unbuntu 10.10, with zmq 2.0.10 and pyzmq 2.0.10-1. I don't recall the problem being nearly as prevalent before I updated my zmq setup (I was running fairly old {py}zmqs). Now it's trivial to trigger it with almost any print statement.

Min, you're 100% right in your assessment of the problem, including async out-of-order messages in a terminal: just do any 'cmd &' in a simple shell, and eventually the command will produce something to stdout that will end up in a weird place. I get gunk all the time in the shells I start my firefox sessions from...

All that said, it's also probably a good idea to get some robustness for the really plain 'print' cases, as Evan suggested, even if it costs us some less-than-elegant codepaths.

[minrk]

After testing several combinations of zeromq/pyzmq, I concluded that wasn't the problem. Moving on to IPython, I rolled back commits via a binary-search style hop around, and found the issue. Good news/bad news time (bad only for me):

Good news: I found/fixed the problem
Bad news: It was my fault.

In consolidating session.msg/socket.send_json calls into session.send here:
8c0b397

I put the execute reply before the flush/sleep used to prevent exactly this thing from happening. Brian was right that we did it, but it wasn't in the frontend, it was in the kernel. Fix has been pushed, and I don't see the issue anymore on my Ubuntu machine.

It's still impossible to guarantee that one arrives before the other with zeromq so the general issue remains, but it shouldn't come up on these trivial examples anymore.

[fperez]

Thanks a lot for tracking this down, Min! And sorry it turned out to be you ;)

Should we close the ticket, or does Evan still want to try to add some more robust (if ugly) special handling of the prompt as discussed earlier?

[epatters]

How about we leave it open but mark it as low priority?

[takluyver]

If we've solved the immediate bug, I'm happy to close it. By the sounds of it, the solution might be to rebuild the Qt code into a "notebook" interface. Perhaps this should be proposed for Google Summer of Code?

[epatters]

Ideas about a Qt notebook have been floating around for some time, but it would supplement, rather than replace, the Qt console. Sometimes the traditional console interface is more convenient than the notebook interface.

But sure, feel free to close the bug, since we have in fact solved the immediate issue.

[minrk]

Yes, a Qt notebook would be a new application. We've been discussing/working on IPython notebooks on and off for years, but a GSoC could be a great way to take another run at it, starting from James Gao's nice HTML work.

I'm fine closing it. If Evan finds a simple way to give the console some stronger defenses against this, that's great, but I don't think this Issue needs to hang over his head.

[takluyver]

Right then.