Add a test for log_call.

Make log_call a little shorter as well, stream_readline() is now a closure.

bootstrapvz/common/tools.py

@@ -11,30 +11,34 @@ def stream_readline(args):
 	for line in iter(stream.readline, ''):
 		q.put((stream, line.strip()))
 
+
 def log_call(command, stdin=None, env=None, shell=False):
 	import subprocess
 	import logging
 	import Queue
 	from multiprocessing.dummy import Pool as ThreadPool
 	from os.path import realpath
+
 	command_log = realpath(command[0]).replace('/', '.')
 	log = logging.getLogger(__name__ + command_log)
 	log.debug('Executing: {command}'.format(command=' '.join(command)))
-	popen_args = {'args':   command,
-	              'env':    env,
-	              'shell':  shell,
-	              'stdin':  subprocess.PIPE,
-	              'stdout': subprocess.PIPE,
-	              'stderr': subprocess.PIPE, }
+
+	process = subprocess.Popen(args=command, env=env, shell=shell,
+	                           stdin=subprocess.PIPE,
+	                           stdout=subprocess.PIPE,
+	                           stderr=subprocess.PIPE)
+
+	def stream_readline(args):
+		stream, q = args
+		for line in iter(stream.readline, ''):
+			q.put((stream, line.strip()))
+
 	if stdin is not None:
-		log.debug('  stdin: {stdin}'.format(stdin=stdin))
-		popen_args['stdin'] = subprocess.PIPE
-		process = subprocess.Popen(**popen_args)
-		process.stdin.write(stdin + "\n")
-		process.stdin.flush()
-		process.stdin.close()
-	else:
-		process = subprocess.Popen(**popen_args)
+	    log.debug('  stdin: {stdin}'.format(stdin=stdin))
+	    process.stdin.write(stdin + "\n")
+	    process.stdin.flush()
+	    process.stdin.close()
+
 	stdout = []
 	stderr = []
 	q = Queue.Queue()

tests/integration/subprocess.sh

@@ -0,0 +1,29 @@
+#!/bin/bash
+
+# Expected input from stdin:
+# streamNo delay message
+# Running the following
+#
+# (cat <<EOF
+# 2 1 one\\\\n
+# 1 2 two\\\\n
+# 1 5 four
+# 1 6 \\\\rNo, three..\\\\n
+# EOF
+# ) | ./subprocess.sh
+#
+# Would result in:
+# one (after a delay of 1 sec. on stderr)
+# two (after a delay of another second on stdout)
+# four (after a delay of three more seconds on stdout)
+# No, three.. (overwrites the line with "four" after a second)
+
+while read line; do
+	[[ -z $line ]] && continue
+	stream=${line%% *}
+	rest=${line#* *}
+	delay=${rest%% *}
+	message=${rest#* }
+	eval "sleep $delay; printf \"$message\" >&$stream" &
+done
+wait

tests/integration/tools_tests.py

@@ -0,0 +1,39 @@
+import os
+from nose.tools import eq_
+from bootstrapvz.common.tools import log_call
+
+subprocess_path = os.path.join(os.path.dirname(os.path.realpath(__file__)), 'subprocess.sh')
+
+
+def setup_logger():
+	import logging
+	root = logging.getLogger()
+	root.setLevel(logging.NOTSET)
+
+	import StringIO
+	output = StringIO.StringIO()
+	string_handler = logging.StreamHandler(output)
+	string_handler.setLevel(logging.DEBUG)
+	root.addHandler(string_handler)
+	return output
+
+
+def test_log_call():
+	logged = setup_logger()
+	fixture = """
+2 0.1 one\\\\n
+1 0.2 two\\\\n
+1 0.5 four
+2 0.6 \\\\rNo, three..
+1 0.8 \\\\rthree
+"""
+	status, stdout, stderr = log_call([subprocess_path], stdin=fixture)
+	eq_(status, 0)
+	eq_(stderr, ['one', 'No, three..'])
+	eq_(stdout, ['two', 'four\rthree'])
+	expected_order = ['one',
+	                  'two',
+	                  'No, three..',  # The "four" is only recorded *after* the process is done (no newline)...
+	                  'four\rthree',  # .. which is why "No, three" comes first
+	                  ]
+	eq_(logged.getvalue().split("\n")[8:-1], expected_order)