From 00780844c79f1ad9116642c193bc58d3504cb067 Mon Sep 17 00:00:00 2001
From: Anders Ingemann <anders@ingemann.de>
Date: Sat, 3 May 2014 19:41:55 +0200
Subject: [PATCH] Add a test for log_call. Make log_call a little shorter as
 well, stream_readline() is now a closure.

---
 bootstrapvz/common/tools.py      | 32 ++++++++++++++------------
 tests/integration/subprocess.sh  | 29 ++++++++++++++++++++++++
 tests/integration/tools_tests.py | 39 ++++++++++++++++++++++++++++++++
 3 files changed, 86 insertions(+), 14 deletions(-)
 create mode 100755 tests/integration/subprocess.sh
 create mode 100644 tests/integration/tools_tests.py

diff --git a/bootstrapvz/common/tools.py b/bootstrapvz/common/tools.py
index db859da..77e6599 100644
--- a/bootstrapvz/common/tools.py
+++ b/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()
diff --git a/tests/integration/subprocess.sh b/tests/integration/subprocess.sh
new file mode 100755
index 0000000..c318e7e
--- /dev/null
+++ b/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
diff --git a/tests/integration/tools_tests.py b/tests/integration/tools_tests.py
new file mode 100644
index 0000000..8669778
--- /dev/null
+++ b/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)