[oe-commits] [openembedded-core] 38/57: utils: qemurunner.py: Add wall clock to 'timeout' logging

[git at git.openembedded.org]

This is an automated email from the git hooks/post-receive script.

rpurdie pushed a commit to branch master-next
in repository openembedded-core.

commit b89c7c9a4ab3b817e6ece5455b809d2c72294ef7
Author: Mark Asselstine <mark.asselstine at windriver.com>
AuthorDate: Fri Dec 1 11:30:11 2017 -0500

    utils: qemurunner.py: Add wall clock to 'timeout' logging
    
    When debugging issues when timeouts are involved it is always best to
    have wall clock times included. This helps give confidence that the
    timeout is in fact run down at the right rate and that no unexpected
    events were the true cause of a premature running down of the
    timeout. Having these times in old logs also helps when debugging
    issues as we have a historic record as to what is a 'typical' time to
    complete an action.
    
    In addition to adding the wall clock times the time to 'login' is now
    printed making it consistent with the time to 'qemu pid'.
    
    Signed-off-by: Mark Asselstine <mark.asselstine at windriver.com>
    Signed-off-by: Ross Burton <ross.burton at intel.com>
---
 meta/lib/oeqa/utils/qemurunner.py | 20 ++++++++++++++------
 1 file changed, 14 insertions(+), 6 deletions(-)

diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py
index 0631d43..8296e98 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -194,7 +194,8 @@ class QemuRunner:
             sys.exit(0)
 
         self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
-        self.logger.debug("waiting at most %s seconds for qemu pid" % self.runqemutime)
+        self.logger.debug("waiting at most %s seconds for qemu pid (%s)" %
+                          (self.runqemutime, time.strftime("%D %H:%M:%S")))
         endtime = time.time() + self.runqemutime
         while not self.is_alive() and time.time() < endtime:
             if self.runqemu.poll():
@@ -208,7 +209,8 @@ class QemuRunner:
             time.sleep(0.5)
 
         if not self.is_alive():
-            self.logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime)
+            self.logger.error("Qemu pid didn't appear in %s seconds (%s)" %
+                              (self.runqemutime, time.strftime("%D %H:%M:%S")))
             # Dump all processes to help us to figure out what is going on...
             ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0]
             processes = ps.decode("utf-8")
@@ -225,7 +227,9 @@ class QemuRunner:
         # We are alive: qemu is running
         out = self.getOutput(output)
         netconf = False # network configuration is not required by default
-        self.logger.debug("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid))
+        self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" %
+                          (time.time() - (endtime - self.runqemutime),
+                           self.qemupid, time.strftime("%D %H:%M:%S")))
         if get_ip:
             cmdline = ''
             with open('/proc/%s/cmdline' % self.qemupid) as p:
@@ -269,7 +273,8 @@ class QemuRunner:
             return False
 
         self.logger.debug("Output from runqemu:\n%s", out)
-        self.logger.debug("Waiting at most %d seconds for login banner" % self.boottime)
+        self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
+                          (self.boottime, time.strftime("%D %H:%M:%S")))
         endtime = time.time() + self.boottime
         socklist = [self.server_socket]
         reachedlogin = False
@@ -298,7 +303,9 @@ class QemuRunner:
                             self.server_socket = qemusock
                             stopread = True
                             reachedlogin = True
-                            self.logger.debug("Reached login banner")
+                            self.logger.debug("Reached login banner in %s seconds (%s)" %
+                                              (time.time() - (endtime - self.boottime),
+                                              time.strftime("%D %H:%M:%S")))
                     else:
                         socklist.remove(sock)
                         sock.close()
@@ -306,7 +313,8 @@ class QemuRunner:
 
 
         if not reachedlogin:
-            self.logger.debug("Target didn't reached login boot in %d seconds" % self.boottime)
+            self.logger.debug("Target didn't reached login boot in %d seconds (%s)" %
+                              (self.boottime, time.strftime("%D %H:%M:%S")))
             tail = lambda l: "\n".join(l.splitlines()[-25:])
             # in case bootlog is empty, use tail qemu log store at self.msg
             lines = tail(bootlog if bootlog else self.msg)

-- 
To stop receiving notification emails like this one, please contact
the administrator of this repository.