Rework logging and output

Use the logs for all the commands output. Tail the log
if there is an error. Create a link to the latest log
so that buildbot can find it easily.

10 files changed, 75 insertions, 48 deletions

diff --git a/Makefile b/Makefile
index 60cb7e7..570d49f 100644
--- a/Makefile
+++ b/Makefile
@@ -4,7 +4,7 @@ COMMANDS_DIR=$(CURDIR)/commands
 HOME_DIR=$(CURDIR)/home
 TOOLS_DIR=$(CURDIR)/tools
 BASE_DIR=$(CURDIR)
-TIME=time -f "\n=== time ===\n\nreal\t%e\nuser\t%U\nsys\t%S\n"
+TIME=time -f "\n= Time =\n\nreal\t%e\nuser\t%U\nsys\t%S\n"
 
 .PHONY: all
 
diff --git a/commands/build b/commands/build
index 0a8b2d4..38cae6b 100755
--- a/commands/build
+++ b/commands/build
@@ -13,7 +13,7 @@ parser.add_argument("module", nargs="?", help="name of the module to build")
 parser.add_argument("--full", action="store_true", help="force a full build")
 args = parser.parse_args()
 
-common.setup()
+common.setup(log_name="build")
 
 if not system.check(skip_if_unchanged=True):
     sys.exit(1)
diff --git a/commands/common.py b/commands/common.py
index e92f798..ac39daf 100644
--- a/commands/common.py
+++ b/commands/common.py
@@ -10,7 +10,7 @@ from devbot import command
 from devbot import git
 
 
-def setup():
+def setup(log_name=None):
     git.set_root_path(base_dir)
 
     args = {"config_dir": os.path.join(base_dir, "config"),
@@ -21,10 +21,10 @@ def setup():
             "prefs_path": os.path.join(base_dir, "prefs"),
             "logs_dir": os.path.join(base_dir, "logs")}
 
+    if log_name:
+        args["log_name"] = log_name
+
     if "SUGAR_BUILDBOT" in os.environ:
         args["relocatable"] = True
 
     config.setup(**args)
-
-    tools_dir = os.path.join(base_dir, "tools")
-    command.set_logger(os.path.join(tools_dir, "log-command"))
diff --git a/commands/pull b/commands/pull
index 5989be6..cca1ff2 100755
--- a/commands/pull
+++ b/commands/pull
@@ -11,7 +11,7 @@ parser = argparse.ArgumentParser()
 parser.add_argument("module", nargs="?", help="name of the module to pull")
 args = parser.parse_args()
 
-common.setup()
+common.setup(log_name="pull")
 
 if args.module:
     success = build.pull_one(args.module)
diff --git a/devbot/build.py b/devbot/build.py
index b51f0cf..31f926d 100644
--- a/devbot/build.py
+++ b/devbot/build.py
@@ -40,8 +40,17 @@ def pull_one(module_name):
 def pull(lazy=False):
     environ.setup()
 
+    to_pull = []
     for module in config.load_modules():
-        if not _pull_module(module, lazy):
+        git_module = module.get_git_module()
+        if not lazy or not os.path.exists(git_module.local):
+            to_pull.append(module)
+
+    if to_pull:
+        print "\n= Pulling =\n"
+
+    for module in to_pull:
+        if not _pull_module(module):
             return False
 
     return True
@@ -60,11 +69,12 @@ def build(full=False):
 
     pull(lazy=True)
 
+    print "\n= Building =\n"
+
     for module in config.load_modules():
-        if state.built_module_is_unchanged(module):
-            print "\n* Skipping unchanged module %s *" % module.name
-        elif not _build_module(module, config.get_log_path("build")):
-            return False
+        if not state.built_module_is_unchanged(module):
+            if not _build_module(module):
+                return False
 
     _ccache_print_stats()
 
@@ -83,13 +93,15 @@ def distribute():
 
 
 def clean():
+    print "= Cleaning =\n"
+
     _empty_dir(config.install_dir)
     _empty_dir(config.get_build_dir())
 
     for module in config.load_modules():
         if not module.out_of_source:
             if module.get_git_module().clean():
-                print "Cleaned %s git repository." % module.name
+                print "* Cleaning %s git repository" % module.name
 
 
 def _ccache_reset():
@@ -97,7 +109,7 @@ def _ccache_reset():
 
 
 def _ccache_print_stats():
-    print "\n=== ccache statistics ===\n"
+    print "= ccache statistics ="
     subprocess.check_call(["ccache", "-s"])
 
 
@@ -109,12 +121,10 @@ def _unlink_libtool_files():
     os.path.walk(config.lib_dir, func, None)
 
 
-def _pull_module(module, lazy=False):
-    git_module = module.get_git_module()
-    if lazy and os.path.exists(git_module.local):
-        return True
+def _pull_module(module):
+    print "* Pulling %s" % module.name
 
-    print "\n=== Pulling %s ===\n" % module.name
+    git_module = module.get_git_module()
 
     try:
         git_module.update()
@@ -206,7 +216,7 @@ _distributors["autotools"] = _distribute_autotools
 
 
 def _build_module(module, log=None):
-    print "\n=== Building %s ===\n" % module.name
+    print "* Building %s" % module.name
 
     source_dir = module.get_source_dir()
 
diff --git a/devbot/command.py b/devbot/command.py
index 8ccef6c..3b2bc30 100644
--- a/devbot/command.py
+++ b/devbot/command.py
@@ -1,7 +1,15 @@
 import subprocess
 import time
 
+from devbot import utils
+
 _logger = None
+_log_path = None
+
+
+def set_log_path(path):
+    global _log_path
+    _log_path = path
 
 
 def set_logger(logger):
@@ -9,32 +17,42 @@ def set_logger(logger):
     _logger = logger
 
 
-def run(args, log=None, test=False, retry=0):
-    print " ".join(args)
+def run(args, test=False, retry=0):
     if test:
+        print " ".join(args)
         return
 
-    full_args = args[:]
-    if log is not None:
-        full_args.insert(0, _logger)
-        full_args.append(log)
+    if _log_path:
+        stdout = open(_log_path, "w")
+        stderr = subprocess.STDOUT
+    else:
+        stdout = None
+        stderr = None
 
     tries = 0
     while tries < retry + 1:
         try:
             tries = tries + 1
-            subprocess.check_call(full_args)
-            return
+            subprocess.check_call(args, stdout=stdout, stderr=stderr)
+            break
         except subprocess.CalledProcessError, e:
+            print "\nCommand failed, tail of %s\n" % _log_path
+            if _log_path:
+                subprocess.call(["tail", _log_path])
+
             if tries < retry + 1:
                 print "Retrying (attempt %d) in 1 minute" % tries
                 time.sleep(60)
             else:
                 raise e
 
+    if stdout:
+        stdout.close()
 
 def run_with_sudo(args, test=False, retry=0):
     args_with_sudo = ["sudo"]
     args_with_sudo.extend(args)
 
+    print " ".join(args_with_sudo)
+ 
     run(args_with_sudo, test=test, retry=retry)
diff --git a/devbot/config.py b/devbot/config.py
index 4eccc92..9637b4e 100644
--- a/devbot/config.py
+++ b/devbot/config.py
@@ -8,6 +8,7 @@ from devbot import distro
 from devbot import plugins
 from devbot import git
 from devbot import utils
+from devbot import command
 
 config_dir = None
 logs_dir = None
@@ -92,6 +93,12 @@ def setup(**kwargs):
     _setup_state_dir(kwargs["state_dir"])
     _setup_install_dir(kwargs["install_dir"], relocatable)
 
+    if "log_name" in kwargs:
+        command.set_log_path(create_log(kwargs["log_name"]))
+
+    if "logger" in kwargs:
+        command.set_logger(kwargs["logger"])
+
 
 def get_source_dir():
     global _source_dir
@@ -105,7 +112,7 @@ def get_build_dir():
     return _build_dir
 
 
-def get_log_path(prefix):
+def create_log(prefix):
     logfile_path = None
     number = 0
 
@@ -118,6 +125,15 @@ def get_log_path(prefix):
 
         number = number + 1
 
+    link_path = os.path.join(logs_dir, "%s.log" % prefix)
+
+    try:
+        os.unlink(link_path)
+    except OSError:
+        pass
+
+    os.symlink(logfile_path, link_path)
+
     return logfile_path
 
 
diff --git a/devbot/distro.py b/devbot/distro.py
index c44fff7..155fb20 100644
--- a/devbot/distro.py
+++ b/devbot/distro.py
@@ -24,7 +24,7 @@ def get_package_manager(test=False, interactive=True):
 
 def print_distro_info():
     info = get_distro_info()
-    print "== Distribution information ==\n"
+    print "\n= Distribution information =\n"
     print "Name: %s" % info.name
     print "Version: %s" % info.version
     print "GNOME version: %s" % info.gnome_version
diff --git a/devbot/run.py b/devbot/run.py
index 34edab9..9bd2a25 100644
--- a/devbot/run.py
+++ b/devbot/run.py
@@ -71,20 +71,11 @@ def collect_logs(source_path, log_name):
             with open(path) as f:
                 logs[filename] = f.read()
 
-    log_path = config.get_log_path(log_name)
+    log_path = config.create_log(log_name)
     with open(log_path, "w") as f:
         for filename, log in logs.items():
             f.write("\n===== %s =====\n\n%s" % (filename, log))
 
-    last_log_path = os.path.join(config.logs_dir, "%s.log" % log_name)
-
-    try:
-        os.unlink(last_log_path)
-    except OSError:
-        pass
-
-    os.symlink(log_path, last_log_path)
-
 
 def _get_random_id():
     return ''.join(random.choice(string.letters) for i in xrange(8))
diff --git a/tools/log-command b/tools/log-command
deleted file mode 100755
index 59a043f..0000000
--- a/tools/log-command
+++ /dev/null
@@ -1,8 +0,0 @@
-#!/bin/bash
-
-toolsdir=`dirname "$0"`
-rootdir=`dirname "$toolsdir"`
-
-${@:(-$#):($#-1)} | tee -a ${@: -1:1}
-
-exit ${PIPESTATUS[0]}