From d9badc17ff5bfd48845a7b5c99f227f18daa7b9d Mon Sep 17 00:00:00 2001
From: algobolson <45948765+algobolson@users.noreply.github.com>
Date: Tue, 31 Mar 2020 08:27:57 -0400
Subject: [PATCH] e2e_basic_start_stop debugging (#937)

wait at least 5s for algod shutdown. better subtest logging
---
 test/scripts/e2e_basic_start_stop.sh |  4 ++--
 test/scripts/e2e_client_runner.py    | 33 ++++++++++++++--------------
 2 files changed, 19 insertions(+), 18 deletions(-)

diff --git a/test/scripts/e2e_basic_start_stop.sh b/test/scripts/e2e_basic_start_stop.sh
index 21d4897c97..3f519e0378 100755
--- a/test/scripts/e2e_basic_start_stop.sh
+++ b/test/scripts/e2e_basic_start_stop.sh
@@ -24,13 +24,13 @@ function verify_at_least_one_running() {
 }
 
 function verify_none_running() {
-    # Shutting down can take some time, so retry up to 2 seconds
+    # Shutting down can take some time, so wait at least 5 seconds
     for TRIES in 1 2 3 4 5; do
         update_running_count
         if [ ${RUNNING_COUNT} -eq 0 ]; then
             return 0
         fi
-        sleep .4
+        sleep 1.4
     done
     echo "algod not expected to be running but it is"
     exit 1
diff --git a/test/scripts/e2e_client_runner.py b/test/scripts/e2e_client_runner.py
index aef12cfe39..b5c6d10eaa 100755
--- a/test/scripts/e2e_client_runner.py
+++ b/test/scripts/e2e_client_runner.py
@@ -109,22 +109,23 @@ def _script_thread_inner(runset, scriptname):
         retcode = -1
     dt = time.time() - start
     if retcode != 0:
-        logger.error('%s failed in %f seconds', scriptname, dt)
-        st = os.stat(cmdlogpath)
-        with open(cmdlogpath, 'r') as fin:
-            if st.st_size > LOG_WHOLE_CUTOFF:
-                fin.seek(st.st_size - LOG_WHOLE_CUTOFF)
-                text = fin.read()
-                lines = text.splitlines()
-                if len(lines) > 1:
-                    # drop probably-partial first line
-                    lines = lines[1:]
-                sys.stderr.write('end of log follows:\n')
-                sys.stderr.write('\n'.join(lines))
-                sys.stderr.write('\n\n')
-            else:
-                sys.stderr.write('whole log follows:\n')
-                sys.stderr.write(fin.read())
+        with runset.lock:
+            logger.error('%s failed in %f seconds', scriptname, dt)
+            st = os.stat(cmdlogpath)
+            with open(cmdlogpath, 'r') as fin:
+                if st.st_size > LOG_WHOLE_CUTOFF:
+                    fin.seek(st.st_size - LOG_WHOLE_CUTOFF)
+                    text = fin.read()
+                    lines = text.splitlines()
+                    if len(lines) > 1:
+                        # drop probably-partial first line
+                        lines = lines[1:]
+                    sys.stderr.write('end of log follows ({}):\n'.format(scriptname))
+                    sys.stderr.write('\n'.join(lines))
+                    sys.stderr.write('\n\n')
+                else:
+                    sys.stderr.write('whole log follows ({}):\n'.format(scriptname))
+                    sys.stderr.write(fin.read())
     else:
         logger.info('finished %s OK in %f seconds', scriptname, dt)
     runset.done(scriptname, retcode == 0, dt)