When Sublime launches an external program (such as when you run a build and it runs python
), it starts two background threads that capture the output of the stdout
and stderr
handles of the program that it's running so that it can display it in the build panel.
Sublime makes sure that only one of those two threads can add data to the output panel at any point, but the data captured by each thread is unbuffered in any way, so as soon as any data appears at the output handle it's queued up for appending to the output panel.
The reason you see this happening is because the print statement sends output to stdout
, but exceptions are written to stderr
. Due to the nature of multi threaded programs, it's indeterminate which of the two threads might capture it's output first, which means that the output of the two handles mix in apparently random ways.
I would imagine that Sublime works this way because if it buffered output to lines by default, programs that generate partial lines at a time would appear to not be running at all.
In practice, while annoying this should not have too much of a deleterious effect on things since generally speaking stdout
is for regular output and stderr
is for error messages, so if both need to be used something untoward is already happening.
It's also possible to create your own custom build target
that mimics what exec
does except with line buffering, in case such a thing is a solid requirement.
As further explanation for the above (and an example of running a program with line buffering), here is an example Python program that demonstrates more clearly what's happening here. Once a second for 10 seconds this generates a .
to stdout
and a -
to stderr
, and then once the 10 seconds has elapsed, it sends a newline to each handle in turn.
import sys
import time
for _ in range(0,10):
sys.stdout.write(".")
sys.stderr.write("-")
sys.stdout.flush()
sys.stderr.flush()
time.sleep(1)
sys.stdout.write("
")
sys.stderr.write("
")
When I run the program with the default Python.sublime-build
, I end up with this:
.--.-..-.--.-.-.-.-.
[Finished in 10.1s]
This demonstrates that not only does the output of stderr
and stdout
blend together, it also does it in weirdly indeterminate ways caused by the multi-threaded nature of the capture.
For example you might expect the output to come out as an alternating series like .-.-.-.-.-.-.-.-.-.-
, but it doesn't; although there are 10 of each item, they don't appear in the same order that we printed them out because the order that each thread gets scheduled to run and notices that there is output to add to the panel is indeterminate.
As I mentioned above, you can create your own custom build target that does what the exec
command does with the exception of holding data in an intermediate buffer and only releasing it to the output panel lines at a time instead of as it appears, which will stop this from happening.
Important Note: Doing line buffering like this doesn't stop the data from stderr
and stdout
from interleaving, it just ensures that the data interleaves whole lines at a time instead of going all "alien chest burster" on each other mid-line. To truly stop the interleave you need to send each handle to a different location (like two panels or sending stderr
to the console).
The full code for something like this is too lengthy to add to an SO answer, so for demonstration purposes I've put the code in this gist. Revision 1 is the base version of the files and revision 2 is the modified versions for buffering, so you can see the differences between the two to better understand the change.
The default exec
command captures output from stderr
and stdout
and sends it directly to the output panel once it's received; as the data arrives at the output panel the command normalizes the line end characters to what Sublime expects to see (for Windows/Mac computers), then adds it to the panel.
The modified version reads the data into a temporary buffer and does the newline normalization right away, then only forwards along any whole lines that it has accumulated, leaving the rest of the data for the next time around. Once the output is finished, any remaining data is sent to the buffer so that everything gets displayed.
In order to use the new target, the sublime-build
file has to have a target
argument added to tell Sublime to use a command other than exec
. The Gist has an example of that for the default Python.sublime-build
, along with an extra key to add to allow the Cancel Build
functionality to work with the custom target.
With the modified build in place, the output of the program becomes this:
----------
..........
[Finished in 10.1s]
Note that a side effect of this is that now you see nothing at all in the build panel for 10 seconds and then all of the output appears all at once, since it can't appear until it's complete; this sort of thing is likely the reason why Sublime doesn't do this by default.
As mentioned above, this doesn't stop the data from interleaving, it just controls how it happens so it happens a line at a time. It's still indeterminate which of the stdout
and stderr
lines appears first.
If you like, you can modify the code starting at line 169 from this:
# Accumulate data into our buffer and only let full lines
# through to the output panel.
if self.listener:
pBuffer += data
nPos = pBuffer.rfind("
")
if nPos >= 0:
self.listener.on_data(self, pBuffer[:nPos+1])
pBuffer = pBuffer[nPos+1:]
To this:
# Accumulate data into our buffer and only let full lines
# through to the output panel; stderr data is held until the
# handle is closed below.
if self.listener:
pBuffer += data
if execute_finished:
nPos = pBuffer.rfind("
")
if nPos >= 0:
self.listener.on_data(self, pBuffer[:nPos+1])
pBuffer = pBuffer[nPos+1:]
That modifies things so that the data for stderr
is stored in a buffer but not released to the output panel until after the program terminates.
Doing that will ensure that there's no interleave, but it also stops you from seeing errors at the point at which they occurred. It also makes it impossible to see errors as they happen if your program is long running and can cause memory usage to increase if there is a lot of error output being buffered but not displayed.
As such I wouldn't recommend this unless you're doing something like running short lived programs where it's less intrusive to have the errors appear at the end.