CHOP-661: Add information to try to zero in on remaining failures.

Make testrunner.py module interpret $INTEGRATION_TEST_VERBOSE environment
variable, setting module global VERBOSE. Enable/disable debug() output based
on that variable, defaulting to VERBOSE True. Add debug() output to
freeport(), including reporting exceptions.
Add debug() output to test_llsdmessage_peer.py, including normal
BaseHTTPRequestHandler output: when VERBOSE is set, don't suppress
log_request() or log_error() output.
Add C++ verbose() function to query $INTEGRATION_TEST_VERBOSE, broken out as
two functions so we only have to interpret the value once. Default to 'true'.
Move C++ commtest_data::getport(variable) function to global namespace, broken
out as two functions to cache the value. Report value received when verbose()
returns true.

indra/llmessage/tests/commtest.h

@@ -34,6 +34,7 @@
 #include "llsd.h"
 #include "llhost.h"
 #include "stringize.h"
+#include <map>
 #include <string>
 #include <stdexcept>
 #include <boost/lexical_cast.hpp>
@@ -43,6 +44,58 @@ struct CommtestError: public std::runtime_error
     CommtestError(const std::string& what): std::runtime_error(what) {}
 };
 
+static bool query_verbose()
+{
+    const char* cbose = getenv("INTEGRATION_TEST_VERBOSE");
+    if (! cbose)
+    {
+        cbose = "1";
+    }
+    std::string strbose(cbose);
+    return (! (strbose == "0" || strbose == "off" ||
+               strbose == "false" || strbose == "quiet"));
+}
+
+bool verbose()
+{
+    // This should only be initialized once.
+    static bool vflag = query_verbose();
+    return vflag;
+}
+
+static int query_port(const std::string& var)
+{
+    const char* cport = getenv(var.c_str());
+    if (! cport)
+    {
+        throw CommtestError(STRINGIZE("missing environment variable" << var));
+    }
+    // This will throw, too, if the value of PORT isn't numeric.
+    int port(boost::lexical_cast<int>(cport));
+    if (verbose())
+    {
+        std::cout << "getport('" << var << "') = " << port << std::endl;
+    }
+    return port;
+}
+
+static int getport(const std::string& var)
+{
+    typedef std::map<std::string, int> portsmap;
+    static portsmap ports;
+    // We can do this with a single map lookup with map::insert(). Either it
+    // returns an existing entry and 'false' (not newly inserted), or it
+    // inserts the specified value and 'true'.
+    std::pair<portsmap::iterator, bool> inserted(ports.insert(portsmap::value_type(var, 0)));
+    if (inserted.second)
+    {
+        // We haven't yet seen this var. Remember its value.
+        inserted.first->second = query_port(var);
+    }
+    // Return the (existing or new) iterator's value.
+    return inserted.first->second;
+}
+
 /**
  * This struct is shared by a couple of standalone comm tests (ADD_COMM_BUILD_TEST).
  */
@@ -71,13 +124,10 @@ struct commtest_data
 
     static int getport(const std::string& var)
     {
-        const char* port = getenv(var.c_str());
-        if (! port)
-        {
-            throw CommtestError("missing $PORT environment variable");
-        }
-        // This will throw, too, if the value of PORT isn't numeric.
-        return boost::lexical_cast<int>(port);
+        // We have a couple consumers of commtest_data::getport(). But we've
+        // since moved it out to the global namespace. So this is just a
+        // facade.
+        return ::getport(var);
     }
 
     bool outcome(const LLSD& _result, bool _success)

indra/llmessage/tests/test_llsdmessage_peer.py

@@ -38,7 +38,7 @@
 sys.path.insert(0, os.path.join(mydir, os.pardir, os.pardir, "lib", "python"))
 from indra.util.fastest_elementtree import parse as xml_parse
 from indra.base import llsd
-from testrunner import freeport, run, debug
+from testrunner import freeport, run, debug, VERBOSE
 
 class TestHTTPRequestHandler(BaseHTTPRequestHandler):
     """This subclass of BaseHTTPRequestHandler is to receive and echo
@@ -72,10 +72,10 @@ def read_xml(self):
 ##         # assuming that the underlying XML parser reads its input file
 ##         # incrementally. Unfortunately I haven't been able to make it work.
 ##         tree = xml_parse(self.rfile)
-##         debug("Finished raw parse\n")
-##         debug("parsed XML tree %s\n" % tree)
-##         debug("parsed root node %s\n" % tree.getroot())
-##         debug("root node tag %s\n" % tree.getroot().tag)
+##         debug("Finished raw parse")
+##         debug("parsed XML tree %s", tree)
+##         debug("parsed root node %s", tree.getroot())
+##         debug("root node tag %s", tree.getroot().tag)
 ##         return llsd.to_python(tree.getroot())
 
     def do_GET(self):
@@ -88,8 +88,10 @@ def do_POST(self):
         self.answer(self.read_xml())
 
     def answer(self, data):
+        debug("%s.answer(%s): self.path = %r", self.__class__.__name__, data, self.path)
         if "fail" not in self.path:
             response = llsd.format_xml(data.get("reply", llsd.LLSD("success")))
+            debug("success: %s", response)
             self.send_response(200)
             self.send_header("Content-type", "application/llsd+xml")
             self.send_header("Content-Length", str(len(response)))
@@ -106,16 +108,21 @@ def answer(self, data):
                                                   ("fail requested",
                                                    "Your request specified failure status %s "
                                                    "without providing a reason" % status))[1])
+            debug("fail requested: %s: %r", status, reason)
             self.send_error(status, reason)
 
-    def log_request(self, code, size=None):
-        # For present purposes, we don't want the request splattered onto
-        # stderr, as it would upset devs watching the test run
-        pass
+    if not VERBOSE:
+        # When VERBOSE is set, skip both these overrides because they exist to
+        # suppress output.
 
-    def log_error(self, format, *args):
-        # Suppress error output as well
-        pass
+        def log_request(self, code, size=None):
+            # For present purposes, we don't want the request splattered onto
+            # stderr, as it would upset devs watching the test run
+            pass
+
+        def log_error(self, format, *args):
+            # Suppress error output as well
+            pass
 
 if __name__ == "__main__":
     # Instantiate an HTTPServer(TestHTTPRequestHandler) on the first free port
@@ -130,4 +137,5 @@ def log_error(self, format, *args):
     # command-line parsing -- and anyway, for C++ integration tests, that's
     # performed in TUT code rather than our own.
     os.environ["PORT"] = str(port)
+    debug("$PORT = %s", port)
     sys.exit(run(server=Thread(name="httpd", target=httpd.serve_forever), *sys.argv[1:]))

indra/llmessage/tests/testrunner.py

@@ -29,14 +29,21 @@
 
 import os
 import sys
+import re
 import errno
 import socket
 
-def debug(*args):
-    sys.stdout.writelines(args)
-    sys.stdout.flush()
-# comment out the line below to enable debug output
-debug = lambda *args: None
+VERBOSE = os.environ.get("INTEGRATION_TEST_VERBOSE", "1") # default to verbose
+# Support usage such as INTEGRATION_TEST_VERBOSE=off -- distressing to user if
+# that construct actually turns on verbosity...
+VERBOSE = not re.match(r"(0|off|false|quiet)$", VERBOSE, re.IGNORECASE)
+
+if VERBOSE:
+    def debug(fmt, *args):
+        print fmt % args
+        sys.stdout.flush()
+else:
+    debug = lambda *args: None
 
 def freeport(portlist, expr):
     """
@@ -78,44 +85,53 @@ def freeport(portlist, expr):
     # pass 'port' to client code
     # call server.serve_forever()
     """
-    # If portlist is completely empty, let StopIteration propagate: that's an
-    # error because we can't return meaningful values. We have no 'port',
-    # therefore no 'expr(port)'.
-    portiter = iter(portlist)
-    port = portiter.next()
-
-    while True:
-        try:
-            # If this value of port works, return as promised.
-            return expr(port), port
-
-        except socket.error, err:
-            # Anything other than 'Address already in use', propagate
-            if err.args[0] != errno.EADDRINUSE:
-                raise
-
-            # Here we want the next port from portiter. But on StopIteration,
-            # we want to raise the original exception rather than
-            # StopIteration. So save the original exc_info().
-            type, value, tb = sys.exc_info()
+    try:
+        # If portlist is completely empty, let StopIteration propagate: that's an
+        # error because we can't return meaningful values. We have no 'port',
+        # therefore no 'expr(port)'.
+        portiter = iter(portlist)
+        port = portiter.next()
+
+        while True:
             try:
+                # If this value of port works, return as promised.
+                value = expr(port)
+
+            except socket.error, err:
+                # Anything other than 'Address already in use', propagate
+                if err.args[0] != errno.EADDRINUSE:
+                    raise
+
+                # Here we want the next port from portiter. But on StopIteration,
+                # we want to raise the original exception rather than
+                # StopIteration. So save the original exc_info().
+                type, value, tb = sys.exc_info()
                 try:
-                    port = portiter.next()
-                except StopIteration:
-                    raise type, value, tb
-            finally:
-                # Clean up local traceback, see docs for sys.exc_info()
-                del tb
-
-        # Recap of the control flow above:
-        # If expr(port) doesn't raise, return as promised.
-        # If expr(port) raises anything but EADDRINUSE, propagate that
-        # exception.
-        # If portiter.next() raises StopIteration -- that is, if the port
-        # value we just passed to expr(port) was the last available -- reraise
-        # the EADDRINUSE exception.
-        # If we've actually arrived at this point, portiter.next() delivered a
-        # new port value. Loop back to pass that to expr(port).
+                    try:
+                        port = portiter.next()
+                    except StopIteration:
+                        raise type, value, tb
+                finally:
+                    # Clean up local traceback, see docs for sys.exc_info()
+                    del tb
+
+            else:
+                debug("freeport() returning %s on port %s", value, port)
+                return value, port
+
+            # Recap of the control flow above:
+            # If expr(port) doesn't raise, return as promised.
+            # If expr(port) raises anything but EADDRINUSE, propagate that
+            # exception.
+            # If portiter.next() raises StopIteration -- that is, if the port
+            # value we just passed to expr(port) was the last available -- reraise
+            # the EADDRINUSE exception.
+            # If we've actually arrived at this point, portiter.next() delivered a
+            # new port value. Loop back to pass that to expr(port).
+
+    except Exception, err:
+        debug("*** freeport() raising %s: %s", err.__class__.__name__, err)
+        raise
 
 def run(*args, **kwds):
     """All positional arguments collectively form a command line, executed as
@@ -144,8 +160,7 @@ def run(*args, **kwds):
     # - [no p] don't use the PATH because we specifically want to invoke the
     #   executable passed as our first arg,
     # - [no e] child should inherit this process's environment.
-    debug("Running %s...\n" % (" ".join(args)))
-    sys.stdout.flush()
+    debug("Running %s...", " ".join(args))
     rc = os.spawnv(os.P_WAIT, args[0], args)
-    debug("%s returned %s\n" % (args[0], rc))
+    debug("%s returned %s", args[0], rc)
     return rc