Better logging levels

3 files changed, 42 insertions, 35 deletions

diff --git a/lorry-controller b/lorry-controller
index 89e20d8..985945f 100755
--- a/lorry-controller
+++ b/lorry-controller
@@ -82,25 +82,25 @@ class LorryController(cliapp.Application):
             self.conf.update_troves(mgr)
             prev_lorries = set(mgr.lorry_state.keys())
             cur_lorries = set(self.conf.lorries.keys())
-            logging.debug("Starting processing.  Previously %d lorries "
-                          "were handled.  We currently have %d defined." % (
+            logging.info("Starting processing.  Previously %d lorries "
+                         "were handled.  We currently have %d defined." % (
                     len(prev_lorries), len(cur_lorries)))
 
             # 1. Handle deletes for any old lorries we no longer want
-            logging.debug("Delete any old lorries...")
+            logging.info("Delete any old lorries...")
             for dead_lorry in prev_lorries - cur_lorries:
-                logging.debug("Dead lorry: %s" % dead_lorry)
+                logging.info("Dead lorry: %s" % dead_lorry)
                 conf_uuid = mgr.lorry_state[dead_lorry]['conf']
                 should_delete = self.conf.configs[conf_uuid]['delete']
                 # TODO: also handle 'unchanged'
                 if should_delete == "always":
-                    logging.debug("TODO: Delete from Trove")
+                    logging.warning("TODO: Delete from Trove")
                 del mgr.lorry_state[dead_lorry]
 
             # 2. Handle creates for any new lorries we now want
-            logging.debug("Create any new lorries...")
+            logging.info("Create any new lorries...")
             for new_lorry in cur_lorries - prev_lorries:
-                logging.debug("New lorry: %s" % new_lorry)
+                logging.info("New lorry: %s" % new_lorry)
                 lorry = self.conf.lorries[new_lorry]
                 conf_uuid = lorry['controller-uuid']
                 conf = self.conf.configs[conf_uuid]
@@ -111,7 +111,7 @@ class LorryController(cliapp.Application):
                     exit, out, err = self.maybe_runcmd(["ssh", "git@localhost",
                                                         "create", new_lorry])
                     if exit != 0:
-                        logging.info("Unable to create repo %s" % new_lorry)
+                        logging.error("Unable to create repo %s" % new_lorry)
                         store_state = False
                 if store_state:
                     mgr.lorry_state[new_lorry] = {
@@ -125,7 +125,7 @@ class LorryController(cliapp.Application):
 
             # 3. For every lorry we have, update the settings if necessary.
             #    and reset the next-due as appropriate.
-            logging.debug("Update active lorry configurations...")
+            logging.info("Update active lorry configurations...")
             updated_count = 0
             for upd_lorry in cur_lorries:
                 if mgr.lorry_state[upd_lorry]['lorry'] != \
@@ -139,11 +139,11 @@ class LorryController(cliapp.Application):
                         'next-due': nextdue,
                     }
                     updated += 1
-            logging.debug("Result: %d/%d lorries needed updating" % (
+            logging.info("Result: %d/%d lorries needed updating" % (
                     updated_count, len(cur_lorries)))
 
             # 3. Iterate all active lorries and see if they're due
-            logging.debug("Iterate active lorries looking for work...")
+            logging.info("Iterate active lorries looking for work...")
             now = time.time()
             lorried = 0
             earliest_due = None
@@ -163,7 +163,7 @@ class LorryController(cliapp.Application):
                 conf = self.conf.configs[conf_uuid]
                 due = state['next-due']
                 lorried += 1
-                logging.debug("Running %d/%d. Lorrying: %s" % (
+                logging.info("Running %d/%d. Lorrying: %s" % (
                         lorried, len(lorries_to_run),lorry))
                 with mgr.runner(lorry) as runner:
                     runner.run_lorry(*self.lorrycmd)
@@ -178,11 +178,12 @@ class LorryController(cliapp.Application):
                     what_early_due = lorry
 
             if earliest_due is None:
-                logging.debug("Lorried %d.  No idea what's next." % lorried)
+                logging.info("Lorried %d.  No idea what's next." % lorried)
             else:
-                logging.debug("Lorried %d.  %s due in %d seconds" % (
+                logging.info("Lorried %d.  %s due in %d seconds" % (
                         lorried, what_early_due, int(earliest_due - now)))
-            logging.debug("All done.")
+            logging.info("All done.")
+
     def rungit(self, args):
         self.runcmd(['git']+args, cwd=os.path.join(self.settings['work-area'],
                                                    'git'))
diff --git a/lorrycontroller/confparser.py b/lorrycontroller/confparser.py
index b78dc54..188ac6b 100644
--- a/lorrycontroller/confparser.py
+++ b/lorrycontroller/confparser.py
@@ -34,12 +34,16 @@ class LorryControllerConfig(object):
         self.duetimes = {}
         self.troves = []
         confpath = os.path.join(app.settings['work-area'], confpath)
-        logging.debug("Parsing configuration: %s" % confpath)
-        with open(confpath, "r") as fh:
-            self._raw_conf = json.load(fh)
+        logging.info("Parsing configuration: %s" % confpath)
+        try:
+            with open(confpath, "r") as fh:
+                self._raw_conf = json.load(fh)
+        except Exception, e:
+            logging.error("Unable to parse: %r" % e)
+            raise
         logging.debug("Validating configuration semantics")
         self._validate__raw_conf()
-        logging.debug("Configuration loaded")
+        logging.info("Configuration loaded")
 
     def _validate__raw_conf(self):
         '''Validate the entire raw config.'''
@@ -127,16 +131,16 @@ class LorryControllerConfig(object):
             try:
                 with open(lorry, "r") as fh:
                     lorry_json = json.load(fh)
-                    for name, content in lorry_json.iteritems():
-                        fullname = os.path.join(entry['prefix'], name)
-                        if self.lorries.get(fullname, None) is not None:
-                            self._give_up("Lorry repeated: %s" % fullname)
-                        content['controller-uuid'] = entry['uuid']
-                        my_lorry_names.add(fullname)
-                        self.lorries[fullname] = content
+                for name, content in lorry_json.iteritems():
+                    fullname = os.path.join(entry['prefix'], name)
+                    if self.lorries.get(fullname, None) is not None:
+                        self._give_up("Lorry repeated: %s" % fullname)
+                    content['controller-uuid'] = entry['uuid']
+                    my_lorry_names.add(fullname)
+                    self.lorries[fullname] = content
             except Exception, e:
-                logging.debug("Unable to parse %s, because of %s. Moving on" %
-                              (lorry, e))
+                logging.warning("Unable to parse %s, because of %s. "
+                                "Moving on" % (lorry, e))
 
         # Now calculate the 'next due' time for every lorry we just parsed
         starttime = time.time() - 1
@@ -180,8 +184,8 @@ class LorryControllerConfig(object):
         self.troves.append(entry)
 
     def update_trove(self, trove, state):
-        logging.debug("Processing trove %s (%s)" % (trove['trovehost'],
-                                                    trove['uuid']))
+        logging.info("Processing trove %s (%s)" % (trove['trovehost'],
+                                                   trove['uuid']))
         # 1. Ensure that if we need to 'ls' the trove, we do it
         now = time.time()
         listcmdargs = ["ssh", "-oStrictHostKeyChecking=no",
diff --git a/lorrycontroller/workingstate.py b/lorrycontroller/workingstate.py
index 68d2ef9..f6f8128 100644
--- a/lorrycontroller/workingstate.py
+++ b/lorrycontroller/workingstate.py
@@ -34,7 +34,7 @@ class LorryFileRunner(object):
         cmdargs.append(self.lorryfile)
         exit, out, err = self.mgr.app.maybe_runcmd(cmdargs)
         if exit == 0:
-            logging.info("Lorry of %s succeeded: %s" % (self.lorryname, out))
+            logging.debug("Lorry of %s succeeded: %s" % (self.lorryname, out))
         else:
             logging.warn("Lorry of %s failed: %s" % (self.lorryname, err))
 
@@ -61,7 +61,8 @@ class WorkingStateManager(object):
         self.trove_state_file = os.path.join(self.workdir,
                                              "last-trove-state.json")
         if os.path.exists(self.lorry_state_file):
-            logging.debug("Loading state file: %s" % self.lorry_state_file)
+            logging.info("Loading lorry state file: %s" %
+                         self.lorry_state_file)
             with open(self.lorry_state_file, "r") as fh:
                 self.lorry_state = json.load(fh)
             for lorry_name, dct in self.lorry_state.iteritems():
@@ -71,18 +72,19 @@ class WorkingStateManager(object):
             self.lorry_state = dict()
 
         if os.path.exists(self.trove_state_file):
-            logging.debug("Loading state file: %s" % self.trove_state_file)
+            logging.info("Loading trove state file: %s" %
+                         self.trove_state_file)
             with open(self.trove_state_file, "r") as fh:
                 self.trove_state = json.load(fh)
         else:
             self.trove_state = dict()
 
     def save_state(self):
-        logging.debug("Serialising state: %s" % self.lorry_state_file)
+        logging.info("Serialising lorry state: %s" % self.lorry_state_file)
         with open(self.lorry_state_file, "w") as fh:
             json.dump(self.lorry_state, fh, sort_keys=True, indent=4)
             fh.write("\n")
-        logging.debug("Serialising state: %s" % self.trove_state_file)
+        logging.info("Serialising trove state: %s" % self.trove_state_file)
         with open(self.trove_state_file, "w") as fh:
             json.dump(self.trove_state, fh, sort_keys=True, indent=4)
             fh.write("\n")