import/export unittest: Improve logging and fix one race condition

Apart from improved logging, one race condition is fixed. If
the destination's status file became available, the port would
be returned immediately, even if it was still “None”. Most of
the time it worked, but not always. Now an additional check
ensures the port evaluates to True.

Signed-off-by: Michael Hanselmann <hansmi@google.com>
Reviewed-by: Guido Trotter <ultrotter@google.com>

lib/impexpd/__init__.py

@@ -25,6 +25,7 @@
 
 import re
 import socket
+import logging
 from cStringIO import StringIO
 
 from ganeti import constants
@@ -320,6 +321,7 @@ class ChildIOProcessor(object):
       if not status_file.GetConnected():
         m = TRANSFER_LOOP_RE.match(msg)
         if m:
+          logging.debug("Connection established")
           status_file.SetConnected()
           return True
 

test/import-export_unittest-helper

@@ -24,6 +24,7 @@
 import os
 import sys
 import errno
+import time
 
 from ganeti import constants
 from ganeti import utils
@@ -36,25 +37,50 @@ TIMEOUT = int(os.getenv("TIMEOUT", 10))
 VALIDITY = int(os.getenv("VALIDITY", 1))
 
 
+def Log(msg, *args):
+  if args:
+    line = msg % args
+  else:
+    line = msg
+
+  sys.stderr.write("%0.6f, pid %s: %s\n" % (time.time(), os.getpid(), line))
+  sys.stderr.flush()
+
+
 def _GetImportExportData(filename):
   try:
     data = utils.ReadFile(filename)
   except EnvironmentError, err:
+    Log("%s = %s", filename, err)
     if err.errno != errno.ENOENT:
       raise
     raise utils.RetryAgain()
 
+  Log("%s = %s", filename, data.strip())
+
   return objects.ImportExportStatus.FromDict(serializer.LoadJson(data))
 
 
 def _CheckConnected(filename):
   if not _GetImportExportData(filename).connected:
+    Log("Not connected")
+    raise utils.RetryAgain()
+
+  Log("Connected")
+
+
+def _CheckListenPort(filename):
+  port = _GetImportExportData(filename).listen_port
+  if not port:
+    Log("No port")
     raise utils.RetryAgain()
+  Log("Listening on %s", port)
+  return port
 
 
 def WaitForListenPort(filename):
-  return utils.Retry(lambda: _GetImportExportData(filename).listen_port,
-                     RETRY_INTERVAL, TIMEOUT)
+  return utils.Retry(_CheckListenPort, RETRY_INTERVAL, TIMEOUT,
+                     args=(filename, ))
 
 
 def WaitForConnected(filename):

test/import-export_unittest.bash

@@ -67,6 +67,10 @@ get_testfile() {
   echo "$(get_testpath)/data/$1"
 }
 
+upto() {
+  echo "$(date '+%F %T'):" "$@" '...'
+}
+
 statusdir=$(mktemp -d)
 trap "rm -rf $statusdir" EXIT
 
@@ -90,6 +94,8 @@ connect_timeout=10
 connect_retries=1
 compress=gzip
 
+upto 'Command line parameter tests'
+
 $impexpd >/dev/null 2>&1 &&
   err "daemon-util succeeded without parameters"
 
@@ -122,10 +128,6 @@ impexpd_helper() {
   $PYTHON $(get_testpath)/import-export_unittest-helper "$@"
 }
 
-upto() {
-  echo "$(date '+%F %T'):" "$@" '...'
-}
-
 reset_status() {
   rm -f $src_statusfile $dst_output $dst_statusfile $dst_output $dst_portfile
 }
@@ -134,6 +136,9 @@ write_data() {
   local fname=${1:-$testdata}
 
   # Wait for connection to be established
+  impexpd_helper $src_statusfile connected
+
+  # And just to be sure, also wait for destination to report as connected
   impexpd_helper $dst_statusfile connected
 
   cat $fname