Hi there!
Using Sublime Text Build 3126 I experience the following behaviour in the build results panel at the bottom:
I execute a Python test script which lists
print(1)
logging.info(1)
print(1)
logging.info(1)
and the build result window writes the logging messages at first and then the two print messages. How does that come? Where should I have a look at to fix that?
Many thanks,
joomie
That’s a symptom of print sending it’s output to stdout and logging sending it’s output to stderr. Since both are going to different files handles, it’s non-deterministic which one of them might appear first in the build output
You would need to either make print send its output to stderr or the logging send it’s output to stdout. I’m not a python guru though, so I don’t know which one of those things is easiest or best to do.
Hi!
Thanks for your reply!
I gonna try to setup a test case to show, but how can I post code snippets here?
I can’t figure it out.
Cheers,
joomie
There are a few ways to go about it.
Anything you paste in that’s indented 4 spaces is treated as preformatted text. If you paste something that’s not already indented, you can select it and press the Preformatted Text button at the top of the post editor (it looks like </>) to cause it to be indented. That would look like this:
def main():
print ("Hello, world!")
if __name__ == "__main__":
main()
You can also achieve this using “code fences”. To that that you can just paste the (non-indented) text and add a row of three backticks on the line preceeding and following it. In the editor, it would look like the following.
```
def main():
print ("Hello, world!")
if __name__ == "__main__":
main()
```
The benefit to this is that you end up with syntax highlighting, which makes the code easier to read:
def main():
print ("Hello, world!")
if __name__ == "__main__":
main()
Okay thanks. It’s difficult to provide a simple example to reproduce the described issue.
What I can report at first is, that the output in the console of the operating system and the build results panel of sublime text differ when I run the same script with unchanged parameters/ conditions.
If by different you mean that they come out in a different order (but have the correct text otherwise), that is to be expected and what I meant above when I said:
The issue is basically that you are writing something to file A and file B , but there is a race condition involved in whether Sublime (or the terminal) read the data from A first or B first, if they happen to buffer the data a little bit before they write it out, and so on. This is what makes the whole operation non-deterministic.
As a simple example, there is this little snippet of python code:
import sys
for x in range(1,5):
print ("I am going to stdout", file=sys.stdout)
print ("I am going to stderr", file=sys.stderr)
This can provide all kinds of output, depending on what is (as far as we can discern) random chance.
The first time I run it in sublime I see:
I am going to stderr
I am going to stderr
I am going to stderr
I am going to stderr
I am going to stderr
I am going to stdout
I am going to stdout
I am going to stdout
I am going to stdout
I am going to stdout
This might make you think, “Oh, stderr is displayed first!”, but then you run it again and see this:
I am going to stdout
I am going to stdout
I am going to stdout
I am going to stdout
I am going to stdout
I am going to stderr
I am going to stderr
I am going to stderr
I am going to stderr
I am going to stderr
Now they’re in the opposite order. What gives?
When I run it from the terminal, I see this:
tmartin:dart:~> python3 test.py
I am going to stdout
I am going to stderr
I am going to stdout
I am going to stderr
I am going to stdout
I am going to stderr
I am going to stdout
I am going to stderr
Now they’re interleaved like you might expect. You might fall into the trap of thinking that Sublime is at fault because it’s not providing the output that you expect to see and the terminal is, but in reality all three of them are doing the same things in a different order and it just so happens that one of those orders is the one that we hoped to see.
The effect here is subtle because the sample size is so small. If you increase the size of the loop to run 100’s of times, you start seeing chunks of first one line and then the other, and it’s possible that even in the terminal you see a couple doubled up.
To prove that it’s a race condition, try the same with the following sample:
import sys, time
for x in range(1,10):
print ("I am going to stdout", file=sys.stdout)
time.sleep (0.1)
print ("I am going to stderr", file=sys.stderr)
time.sleep (0.1)
Now everything interleaves like you would expect it to, because the sleep allows for (depending on your machine and other factors) plenty of time between each print statement for Sublime or the terminal to capture and display the lines as they’re generated.
If you imagine that instead of calls to sleep you have your own code in there, and how long each such call takes varies slightly depending on what the software happens to be doing at any particular point in time, you can see that sometimes things may be an issue and sometimes they may not.
The only way to fix a race condition properly is to remove the race by adding proper synchronization between the racing code paths to ensure that they operate at the appropriate time. The easiest way to do that would be to output all of the data to the same file.
As a fun aside, this sort of bug is often called a heisenbug because you might notice things going weirdly wrong, but when you add in logging to see what it’s doing, it works just fine (due to small delays spent logging). Or my particular favorite, it doesn’t work in the real world but when you run it in the debugger, the overhead of debugging slows everything down just enough to make it work.
Pretty sure this is why old programmers have beards; so they have something to tug at in frustration when things go wonky.
Hi!
many thanks for that very detailed explanation.
When I run the script one time in the Windows DOS command line and the other time in Sublime Text I get different outputs:
DOS console:
C:\Users\<user_name>\Documents\dev\projects\xplane\xassistant\dev\info_airports>C:\Users\<user_name>\Anaconda3\python info_airports.py
[14:20:43] DEBUG : Program start
[14:20:44] INFO : Download of ICAO codes for country 'Ă…land' ...
[14:20:46] INFO : Download of ICAO codes for sub country 'Ă…land_Jomala' ...
[14:20:47] INFO : Download of ICAO codes for sub country 'Ă…land_Kumlinge' ...
[14:20:48] DEBUG : Downloaded 2 SkyVector ICAO codes in 1 countries.
[14:20:48] DEBUG : Collected 2 ICAO codes in 1 countries from file 'manual_country_icaos.lst'.
[14:20:48] INFO : Download of airport 'EFKG.html' in 'Ă…land' ...
[14:20:50] INFO : Download of airport 'EFMA.html' in 'Ă…land' ...
[14:20:53] INFO : Download of airport 'EGYP.html' in 'Falkland Islands' ...
[14:20:55] INFO : Wrote log file to 'C:/Users/<user_name>/Documents/dev/projects/xplane/xassistant/dev/info_airports/info_airports.log'
[14:20:55] DEBUG : Program end
C:\Users\<user_name>\Documents\dev\projects\xplane\xassistant\dev\info_airports>
Sublime Test Build Results:
JarSublime launches C:\Users\<user_name>\Documents\dev\projects\xplane\xassistant\dev\info_airports\info_airports.py
[14:19:36] DEBUG : Program start
[14:19:42] DEBUG : Downloaded 2 SkyVector ICAO codes in 1 countries.
[14:19:42] DEBUG : Collected 2 ICAO codes in 1 countries from file 'manual_country_icaos.lst'.
[14:19:47] INFO : Download of airport 'EGYP.html' in 'Falkland Islands' ...
[14:19:50] INFO : Wrote log file to 'C:/Users/<user_name>/Documents/dev/projects/xplane/xassistant/dev/info_airports/info_airports.log'
[14:19:50] DEBUG : Program end
[Finished in 13.7s]
I wish there is a way to have some output in Sublime Text which behaves exactly like a console output? Probably setting a low buffer size or similar? I see that I’m not a 100% IT guy. 
The info level log messages go all to stdout I guess. But just looking at the info level messages shows differences.
The logger also writes into a .log file. It’s content equals the output of the console as intended.