For years I have used Jenkins to manage all my automated Mac and iOS builds. I have jobs set up to build and release apps “on demand,” as well as integration builds that kick off whenever a change is made to a pertinent source code repository.

For years I have also put up with a small but vexing nuisance that when something goes wrong with a build, I have to search in the most unlikely place for pertinent informational messages printed by my build scripts: at the very bottom of the log.

I had chalked it up for so long to being a nuanced Jenkins bug, that I never took the time to get down to basics and really unwrap what is going on. Today, I did that, and also came up with an easy solution.

I use a custom script to drive the whole process for each of my automated builds. This script is responsible for printing diagnostic information and for invoking other tools (such as xcodebuild) to get the actual work of building, testing, and uploading done.

The problem with the misplaced log lines in my console output has to do with a feature of the scripting language I use to drive the process: standard output buffering. I use Python, but the problem could also affect you if you use a language such as Ruby to drive your automation.

Here’s a contrived example of a build script that will exhibit the problem. If you create a new, empty Jenkins build job, and configure it with a single “Execute Shell” build task:

#!/usr/bin/python 

import os

print "start"
os.system("ls -ld /Applications/TextEdit.app")
print "end"

You will find the generated console output upon “building” this job is demonstrably out of order:

[workspace] $ /usr/bin/python /var/folders/wh/f_vmqvxx34d69c1pm191t0tr0000gq/T/hudson321577740740596707.sh
drwxr-xr-x@ 3 root  wheel  102 Dec 13 14:00 /Applications/TextEdit.app
start
end

The message from the “ls” subprocess prints right away, but Python buffers the output until it’s done running, leading a nonsensical printing of the “start” and “end” messages after the job is completely done.

Now I will make a tiny change, passing the “-u” parameter to the Python invocation in the script. This option is documented to “Force stdin, stdout and stderr to be totally unbuffered”:

#!/usr/bin/python -u

Running the job again in Jenkins produces the expected output in Jenkins:

[workspace] $ /usr/bin/python -u /var/folders/wh/f_vmqvxx34d69c1pm191t0tr0000gq/T/hudson3255283214356026397.sh
start
drwxr-xr-x@ 3 root  wheel  102 Dec 13 14:00 /Applications/TextEdit.app
end

This is a small annoyance in this example, but in a real-world scenario it means that the pertinent xcodebuild invocation, which I print to the console before calling, will now show up where it belongs in the console log, making it much easier for me to reason about the behavior of my automated builds when they aren’t working as they should.