Bug 1536238 - Expand mozprocess debug logging; r=whimboo
authorGeoff Brown <gbrown@mozilla.com>
Tue, 19 Mar 2019 15:07:02 +0000
changeset 465029 6ec637c03b247073c55894de1108d4b89f828dcd
parent 465028 bb9915defb870047b2ae2b3bf7fa66d01dc472f2
child 465030 dbe9eae80e634ad11b57b662e4baa34c4089227e
push id35730
push userrmaries@mozilla.com
push dateTue, 19 Mar 2019 21:51:47 +0000
treeherdermozilla-central@4f6d8ed9e948 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerswhimboo
bugs1536238
milestone68.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1536238 - Expand mozprocess debug logging; r=whimboo Add debug() for the process handler and process reader classes, and add a few debug() calls that I am interested in. Differential Revision: https://phabricator.services.mozilla.com/D23946
testing/mozbase/mozprocess/mozprocess/processhandler.py
--- a/testing/mozbase/mozprocess/mozprocess/processhandler.py
+++ b/testing/mozbase/mozprocess/mozprocess/processhandler.py
@@ -736,16 +736,22 @@ falling back to not using job objects fo
         # the args together since this is how Popen uses it.  Allow for that.
         if isinstance(self.cmd, list):
             if self.args is not None:
                 raise TypeError("cmd and args must not both be lists")
             (self.cmd, self.args) = (self.cmd[0], self.cmd[1:])
         elif self.args is None:
             self.args = []
 
+    def debug(self, msg):
+        if not MOZPROCESS_DEBUG:
+            return
+        cmd = self.cmd.split(os.sep)[-1:]
+        print("DBG::MOZPROC ProcessHandlerMixin {} | {}".format(cmd, msg))
+
     @property
     def timedOut(self):
         """True if the process has timed out for any reason."""
         return self.didTimeout
 
     @property
     def outputTimedOut(self):
         """True if the process has timed out for no output."""
@@ -809,17 +815,20 @@ falling back to not using job objects fo
         if not hasattr(self, "proc"):
             raise RuntimeError("Process hasn't been started yet")
 
         self.proc.kill(sig=sig)
 
         # When we kill the the managed process we also have to wait for the
         # reader thread to be finished. Otherwise consumers would have to assume
         # that it still has not completely shutdown.
-        return self.wait()
+        rc = self.wait()
+        if rc is None:
+            self.debug("kill: wait failed -- process is still alive")
+        return rc
 
     def poll(self):
         """Check if child process has terminated
 
         Returns the current returncode value:
         - None if the process hasn't terminated yet
         - A negative number if the process was killed by signal N (Unix only)
         - '0' if the process ended without failures
@@ -877,16 +886,17 @@ falling back to not using job objects fo
         # Thread.join() blocks the main thread until the reader thread is finished
         # wake up once a second in case a keyboard interrupt is sent
         if self.reader.thread and self.reader.thread is not threading.current_thread():
             count = 0
             while self.reader.is_alive():
                 self.reader.join(timeout=1)
                 count += 1
                 if timeout is not None and count > timeout:
+                    self.debug("wait timeout for reader thread")
                     return None
 
         self.returncode = self.proc.wait()
         return self.returncode
 
     @property
     def pid(self):
         if not hasattr(self, "proc"):
@@ -977,16 +987,21 @@ class ProcessReader(object):
         self.stderr_callback = stderr_callback or (lambda line: True)
         self.finished_callback = finished_callback or (lambda: True)
         self.timeout_callback = timeout_callback or (lambda: True)
         self.timeout = timeout
         self.output_timeout = output_timeout
         self.thread = None
         self.didOutputTimeout = False
 
+    def debug(self, msg):
+        if not MOZPROCESS_DEBUG:
+            return
+        print("DBG::MOZPROC ProcessReader | {}".format(msg))
+
     def _create_stream_reader(self, name, stream, queue, callback):
         thread = threading.Thread(name=name,
                                   target=self._read_stream,
                                   args=(stream, queue, callback))
         thread.daemon = True
         thread.start()
         return thread
 
@@ -1014,16 +1029,17 @@ class ProcessReader(object):
                                                        self.stderr_callback)
         self.thread = threading.Thread(name='ProcessReader',
                                        target=self._read,
                                        args=(stdout_reader,
                                              stderr_reader,
                                              queue))
         self.thread.daemon = True
         self.thread.start()
+        self.debug("ProcessReader started")
 
     def _read(self, stdout_reader, stderr_reader, queue):
         start_time = time.time()
         timed_out = False
         timeout = self.timeout
         if timeout is not None:
             timeout += start_time
         output_timeout = self.output_timeout
@@ -1045,28 +1061,30 @@ class ProcessReader(object):
                     break
             else:
                 if output_timeout is not None:
                     output_timeout = now + self.output_timeout
                 callback(line.rstrip())
             if timeout is not None and now > timeout:
                 timed_out = True
                 break
+        self.debug("_read loop exited")
         # process remaining lines to read
         while not queue.empty():
             line, callback = queue.get(False)
             callback(line.rstrip())
         if timed_out:
             self.timeout_callback()
         if stdout_reader:
             stdout_reader.join()
         if stderr_reader:
             stderr_reader.join()
         if not timed_out:
             self.finished_callback()
+        self.debug("_read exited")
 
     def is_alive(self):
         if self.thread:
             return self.thread.is_alive()
         return False
 
     def join(self, timeout=None):
         if self.thread: