Realtime console output for parallel threaded Python fabric command

[Michael Reinhardt]

We have a Python fabric command that runs in parallel across several hosts, something like this:

    $ fab --hosts=prod1.server,prod2.server,prod3.server --parallel cache_copy

This will copy cache to the production servers listed in parallel. There is various logging that occurs throughout the process to indicate how far along we are since it can take hours for the XXgig cache directories. Since the copying is happening concurrently, the output when run on the command line comes back interlaced in real-time, like so:

    [prod1.server] Executing task 'cache_copy'

    [prod2.server] Executing task 'cache_copy'

    [prod3.server] Executing task 'cache_copy'

    2014-09-16 10:02:29.688243

    [prod1.server] INFO: rsyncing cache dir

    [prod1.server] run: rsync -a -q cache.server:"repo/cache/some.site.com" \

                                                 "repo/cache/."

    2014-09-16 10:02:29.716345

    [prod2.server] INFO: rsyncing cache dir

    [prod2.server] run: rsync -a -q cache.server:"repo/cache/some.site.com" \

                                                 "repo/cache/."

    2014-09-16 10:02:29.853275

    [prod3.server] INFO: rsyncing cache dir

    [prod3.server] run: rsync -a -q cache.server:"repo/cache/some.site.com" \

                                                 "repo/cache/."

    2014-09-16 10:02:29.984154

    [prod1.server] INFO: Reloading nginx config

    [prod1.server] run: sbin/nginx -s reload -c "repo/nginx.conf"

    2014-09-16 10:02:30.025155

    [prod2.server] INFO: Reloading nginx config

    [prod2.server] run: sbin/nginx -s reload -c "repo/nginx.conf"

    2014-09-16 10:02:30.100169

    [prod1.server] SUCCESS: CACHE COPY COMPLETE

    2014-09-16 10:02:30.181938

    [prod2.server] SUCCESS: CACHE COPY COMPLETE

    2014-09-16 10:02:30.331402

    [prod3.server] INFO: Reloading nginx config

    [prod3.server] run: sbin/nginx -s reload -c "repo/nginx.conf"

    2014-09-16 10:02:30.559271

    [prod3.server] SUCCESS: CACHE COPY COMPLETE

    Done.

However, when the task is run through Jenkins, the console output does not display until all tasks are done because Jenkins groups the output AFTER the threads are joined when all threads are complete. So, once all commands are complete the output looks like this:

    [prod1.server] Executing task 'cache_copy'

    2014-09-16 10:02:29.688243

    [prod1.server] INFO: rsyncing cache dir

    [prod1.server] run: rsync -a -q cache.server:"repo/cache/some.site.com" \

                                                 "repo/cache/."

    2014-09-16 10:02:29.984154

    [prod1.server] INFO: Reloading nginx config

    [prod1.server] run: sbin/nginx -s reload -c "repo/nginx.conf"

    2014-09-16 10:02:30.100169

    [prod1.server] SUCCESS: CACHE COPY COMPLETE

    [prod2.server] Executing task 'cache_copy'

    2014-09-16 10:02:29.716345

    [prod2.server] INFO: rsyncing cache dir

    [prod2.server] run: rsync -a -q cache.server:"repo/cache/some.site.com" \

                                                 "repo/cache/."

    2014-09-16 10:02:30.025155

    [prod2.server] INFO: Reloading nginx config

    [prod2.server] run: sbin/nginx -s reload -c "repo/nginx.conf"

    2014-09-16 10:02:30.181938

    [prod2.server] SUCCESS: CACHE COPY COMPLETE

    [prod3.server] Executing task 'cache_copy'

    2014-09-16 10:02:29.853275

    [prod3.server] INFO: rsyncing cache dir

    [prod3.server] run: rsync -a -q cache.server:"repo/cache/some.site.com" \

                                                 "repo/cache/."

    2014-09-16 10:02:30.331402

    [prod3.server] INFO: Reloading nginx config

    [prod3.server] run: sbin/nginx -s reload -c "repo/nginx.conf"

    2014-09-16 10:02:30.559271

    [prod3.server] SUCCESS: CACHE COPY COMPLETE

    Done.

While this is more readable, it's not ideal because we'd like to keep track of the state of the process by reading the console output in realtime. Note that when this fabric command is run *without* the `--parallel` option the console output *does occur in realtime*, however obviously this is not workable because the serial process takes much longer to run.

I haven't been able to find a setting in Jenkins that will disable this thread grouping. Does anyone have any ideas?

Thanks.

[Chris Z.]

Hi,

What is this fab ? Python scripts with shebang (self executable)? python -u usually helps with jenkins python output issues.

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Chris Z.]

-u

Force stdin, stdout and stderr to be totally unbuffered. On systems where it matters, also put stdin, stdout and stderr in binary mode.

Note that there is internal buffering in file.readlines() and File Objects (for line in sys.stdin) which is not influenced by this option. To work around this, you will want to use file.readline()inside a while 1: loop.

[Michael Reinhardt]

Thanks for the reply!

fab is fabric http://www.fabfile.org/en/latest/ - a Python tool for deploying to multiple servers.

I noticed the -u option can also be applied with PYTHONUNBUFFERED, so I'll try `PYTHONUNBUFFERED=1 && fab ...etc...` for Monday's run and report back afterwards.