wrappercheck: augment output of daemon with time stamps

Useful for correlating events in the daemon with events in testing.
We need to use a process group to deliver SIGINT/SIGTERM, otherwise
we cannot be sure that we catch all processes created by the daemon.

The return code of the daemon was not checked before (accidentally?!)
and this patch does not change that. Might be fixed in the future.

2 files changed, 68 insertions, 10 deletions

diff --git a/test/logger.py b/test/logger.py
new file mode 100755
index 00000000..5219d6ef
--- /dev/null
+++ b/test/logger.py
@@ -0,0 +1,45 @@
+#! /usr/bin/python
+#
+# Copyright (C) 2014 Intel Corporation
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) version 3.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+
+# Augments stdin by adding a "log starting" preamble and "log ending"
+# footer and a time stamp to each line. Flushes after each line
+# and ignores SIGTERM and SIGINT, in order to not loose unprocessed
+# output.
+
+import os
+import re
+import signal
+import sys
+import time
+
+def now():
+    return time.strftime('%H:%M:%S', time.gmtime())
+
+signal.signal(signal.SIGTERM, lambda x,y: sys.stdout.write('--- SIGTERM at %s ---\n' % now()))
+signal.signal(signal.SIGINT, lambda x,y: sys.stdout.write('--- SIGINT at %s ---\n' % now()))
+
+sys.stdout.write('--- log starting at %s ---\n' % now())
+sys.stdout.flush()
+
+while True:
+    line = sys.stdin.readline()
+    if not line:
+        break
+    if not line[0].isspace():
+        sys.stdout.write(now() + ' ')
+    sys.stdout.write(line)
+    sys.stdout.flush()
+
+sys.stdout.write('--- log ending at %s ---\n' % now())
+sys.stdout.flush()
diff --git a/test/wrappercheck.sh b/test/wrappercheck.sh
index 5145c711..be0d6c1d 100755
--- a/test/wrappercheck.sh
+++ b/test/wrappercheck.sh
@@ -59,7 +59,11 @@ if [ "$DAEMON_LOG" ] && [ "$WAIT_FOR_DAEMON_OUTPUT" ]; then
 fi
 
 ( set +x; echo >&2 "*** starting ${BACKGROUND[0]} as background daemon, output to ${DAEMON_LOG:-stderr}" )
-( set -x; exec >>${DAEMON_LOG:-&2} 2>&1; exec env "${ENV[@]}" "${BACKGROUND[@]}" ) &
+# We need to create a process group so that we can kill all processes started by the sub-shell.
+# ${BACKGROUND[*]} is used instead of ${BACKGROUND[@]} because although the later should have
+# avoided expansion of words (good!) somehow the quoting got messed up in practice (bad!).
+( set -x; exec >>${DAEMON_LOG:-&2} 2>&1; exec env "${ENV[@]}" setsid /bin/bash -c "set -x -o pipefail; ${BACKGROUND[*]} | $(dirname $0)/logger.py" ) &
+
 BACKGROUND_PID=$!
 PIDS+="$BACKGROUND_PID"
 
@@ -89,18 +93,27 @@ else
 fi
 
 ( set +x; echo >&2 "*** killing and waiting for ${BACKGROUND[0]}" )
-kill -INT $BACKGROUND_PID && kill -TERM $BACKGROUND_PID || true
-perl -e "sleep(60); kill(9, $BACKGROUND_PID);" &
-KILL_PID=$!
+if kill -INT -$BACKGROUND_PID 2>/dev/null && kill -TERM -$BACKGROUND_PID 2>/dev/null; then
+    perl -e "sleep(60); kill(9, -$BACKGROUND_PID);" &
+    KILL_PID=$!
+else
+    KILL_PID=
+fi
 set +e
 wait $BACKGROUND_PID
-msg=$(LC_ALL=C kill -KILL $KILL_PID 2>&1)
 SUBRET=$?
-if echo "$msg" | grep -q 'No such process'; then
-    # Consider this a success.
-    SUBRET=0
-else
-    echo "$msg"
+case $SUBRET in 0|130|137|139|143) SUBRET=0;; # 130 and 143 indicate that it was killed, probably by us, which is okay
+esac
+SUBRET=0 # TODO: don't ignore daemon results
+if [ "$KILL_PID" ]; then
+    msg=$(LC_ALL=C kill -KILL $KILL_PID 2>&1)
+    if echo "$msg" | grep -q 'No such process'; then
+        # Consider this a success.
+        SUBRET=0
+    else
+        echo "$msg"
+    fi
+    wait $KILL_PID
 fi
 set -e
 if [ $RET = 0 ]; then