cerbero: Implement timestamp printing for messages

This allows easy measurement of the time taken by each recipe and the
total time spent by Cerbero. The format is:

[HH:MM:SS] [(1/N) recipe_name -> fetch ]

https://bugzilla.gnome.org/show_bug.cgi?id=797288

2 files changed, 21 insertions, 5 deletions

diff --git a/cerbero/main.py b/cerbero/main.py
index 5a503be5..e1933157 100644
--- a/cerbero/main.py
+++ b/cerbero/main.py
@@ -30,6 +30,7 @@ import errno
 import logging
 import traceback
 import os
+import time
 
 from cerbero import config, commands
 from cerbero.errors import UsageError, FatalError, BuildStepError, \
@@ -47,10 +48,10 @@ class Main(object):
             m.warning(_("Running as root"))
 
         self.check_in_cerbero_shell()
-        self.init_logging()
         self.create_parser()
         self.load_commands()
         self.parse_arguments(args)
+        self.init_logging()
         self.load_config()
         self.run_command()
 
@@ -70,12 +71,16 @@ class Main(object):
 
     def init_logging(self):
         ''' Initialize logging '''
+        if self.args.timestamps:
+            m.START_TIME = time.clock()
         logging.getLogger().setLevel(logging.INFO)
         logging.getLogger().addHandler(logging.StreamHandler())
 
     def create_parser(self):
         ''' Creates the arguments parser '''
         self.parser = argparse.ArgumentParser(description=_(description))
+        self.parser.add_argument('-t', '--timestamps', action='store_true', default=False,
+                help=_('Print timestamps with every message printed'))
         self.parser.add_argument('-c', '--config', action='append', type=str, default=None,
                 help=_('Configuration file used for the build'))
 
diff --git a/cerbero/utils/messages.py b/cerbero/utils/messages.py
index 6fee5f5d..8ed967cb 100644
--- a/cerbero/utils/messages.py
+++ b/cerbero/utils/messages.py
@@ -17,20 +17,31 @@
 # Boston, MA 02111-1307, USA.
 
 import sys
+import time
+import datetime
 
 
 ACTION_TPL = '-----> %s'
 STEP_TPL = '[(%s/%s) %s -> %s ]'
+START_TIME = None
+
+
+def _output(msg, fd):
+    global START_TIME
+    prefix = ''
+    if START_TIME is not None:
+        prefix = str(datetime.timedelta(seconds=int(time.clock() - START_TIME)))
+        prefix += ' '
+    fd.write(prefix + msg + '\n')
+    fd.flush()
 
 
 def message(msg):
-    sys.stdout.write(msg + '\n')
-    sys.stdout.flush()
+    _output(msg, sys.stdout)
 
 
 def error(msg):
-    sys.stderr.write(msg + '\n')
-    sys.stderr.flush()
+    _output(msg, sys.stderr)
 
 
 def warning(msg):