Add some debug entries to executor

To try to understand the delay after a playbook completes, add
some debug entries, some of which may be useful on their own.

Change-Id: I7a207574c333aceb0d4d7f028ada0eb10cfdc8b7
diff --git a/zuul/executor/server.py b/zuul/executor/server.py
index 758fd2a..981034d 100644
--- a/zuul/executor/server.py
+++ b/zuul/executor/server.py
@@ -681,6 +681,13 @@
     RESULT_UNREACHABLE = 3
     RESULT_ABORTED = 4
 
+    RESULT_MAP = {
+        RESULT_NORMAL: 'RESULT_NORMAL',
+        RESULT_TIMED_OUT: 'RESULT_TIMED_OUT',
+        RESULT_UNREACHABLE: 'RESULT_UNREACHABLE',
+        RESULT_ABORTED: 'RESULT_ABORTED',
+    }
+
     def __init__(self, executor_server, job):
         logger = logging.getLogger("zuul.AnsibleJob")
         self.log = AnsibleJobLogAdapter(logger, {'job': job.unique})
@@ -1283,11 +1290,13 @@
             for line in iter(self.proc.stdout.readline, b''):
                 line = line[:1024].rstrip()
                 self.log.debug("Ansible output: %s" % (line,))
+            self.log.debug("Ansible output terminated")
             ret = self.proc.wait()
+            self.log.debug("Ansible exit code: %s" % (ret,))
         finally:
             if timeout:
                 watchdog.stop()
-        self.log.debug("Ansible exit code: %s" % (ret,))
+                self.log.debug("Stopped watchdog")
 
         with self.proc_lock:
             self.proc = None
@@ -1318,5 +1327,8 @@
         if success is not None:
             cmd.extend(['-e', 'success=%s' % str(bool(success))])
 
-        return self.runAnsible(
+        result, code = self.runAnsible(
             cmd=cmd, timeout=timeout, trusted=playbook.trusted)
+        self.log.debug("Ansible complete, result %s code %s" % (
+            self.RESULT_MAP[result], code))
+        return result, code