Improve debug logging

Several changes to the logging using in all processes:
* Disable logging of bus messages by default (massively cleans up the logs)
* Add "mycroft.debug.log" bus message.  It supports the data={"bus": True/False} as well as
  data={"log": LEVEL}, where level is a Python logging level.

CLI now supports several commands:
* ```:log level XXX``` where XXX is the name of a standard Python level (e.g. 'debug')
* ```:log bus on``` or ```:log bus off```
* Removed the requirement for "log" in ```:clear log```.  ```:clear``` works now.

mycroft/client/text/text_client.py

@@ -222,11 +222,17 @@ class LogMonitorThread(Thread):
 
                 # Check if file has been modified since last read
                 if not st_results.st_mtime == self.st_results.st_mtime:
-                    self.read_file_from(self.st_results.st_size)
+                    read_from = self.st_results.st_size
                     self.st_results = st_results
+                    if st_results.st_size < read_from:
+                        st
+                    self.read_file_from(self.st_results.st_size)
+
                     set_screen_dirty()
-            finally:
+            except OSError:
-                time.sleep(0.1)
+                # ignore any file IO exceptions, just try again
+                pass
+            time.sleep(0.1)
 
     def read_file_from(self, bytefrom):
         global meter_cur
@@ -856,7 +862,7 @@ help_struct = [
       (":meter (show|hide)",    "display the microphone level"),
       (":keycode (show|hide)",  "display typed key codes (mainly debugging)"),
       (":history (# lines)",    "set size of visible history buffer"),
-      (":clear log",            "flush the logs")
+      (":clear",                "flush the logs")
      ]
     ),
     (
@@ -866,7 +872,9 @@ help_struct = [
       (":filter remove 'STR'",  "removes a log filter"),
       (":filter (clear|reset)", "reset filters"),
       (":filter (show|list)",   "display current filters"),
-      (":find 'STR'",           "show logs containing 'str'")
+      (":find 'STR'",           "show logs containing 'str'"),
+      (":log level (debug|info|error)", "set logging level"),
+      (":log bus (on|off)",     "control logging of messagebus messages")
      ]
     ),
     (
@@ -1044,7 +1052,11 @@ def _get_cmd_param(cmd, keyword):
     # Returns parameter to a command.  Will de-quote.
     # Ex: find 'abc def'   returns: abc def
     #    find abc def     returns: abc def
-    cmd = cmd.replace(keyword, "").strip()
+    if type(keyword) is list:
+        for w in keyword:
+            cmd = cmd.replace(w, "").strip()
+    else:
+        cmd = cmd.replace(keyword, "").strip()
     if not cmd:
         return None
 
@@ -1071,8 +1083,6 @@ def handle_cmd(cmd):
         show_help()
     elif "exit" in cmd or "quit" in cmd:
         return 1
-    elif "clear" in cmd and "log" in cmd:
-        clear_log()
     elif "keycode" in cmd:
         # debugging keyboard
         if "hide" in cmd or "off" in cmd:
@@ -1107,6 +1117,19 @@ def handle_cmd(cmd):
 
         rebuild_filtered_log()
         add_log_message("Filters: " + str(log_filters))
+    elif "clear" in cmd:
+        clear_log()
+    elif "log" in cmd:
+        # Control logging behavior in all Mycroft processes
+        if "level" in cmd:
+            level = _get_cmd_param(cmd, ["log", "level"])
+            bus.emit(Message("mycroft.debug.log", data={'level': level}))
+        elif "bus" in cmd:
+            state = _get_cmd_param(cmd, ["log", "bus"]).lower()
+            if state in ["on", "true", "yes"]:
+                bus.emit(Message("mycroft.debug.log", data={'bus': True}))
+            elif state in ["off", "false", "no"]:
+                bus.emit(Message("mycroft.debug.log", data={'bus': False}))
     elif "history" in cmd:
         # extract last word(s)
         lines = int(_get_cmd_param(cmd, "history"))

mycroft/util/__init__.py

@@ -63,6 +63,8 @@ def resolve_resource_file(res_name):
 
     Args:
         res_name (str): a resource path/name
+    Returns:
+        str: path to resource or None if no resource found
     """
     config = mycroft.configuration.Configuration.get()
 
@@ -396,28 +398,59 @@ def wait_for_exit_signal():
         pass
 
 
+
+_log_all_bus_messages = False
 def create_echo_function(name, whitelist=None):
+    """ Standard logging mechanism for Mycroft processes.
+
+    This handles the setup of the basic logging for all Mycroft
+    messagebus-based processes.
+
+    Args:
+        name (str): Reference name of the process
+        whitelist (list, optional): List of "type" strings.  If defined, only
+                                    messages in this list will be logged.
+
+    Returns:
+        func: The echo function
+    """
+
     from mycroft.configuration import Configuration
     blacklist = Configuration.get().get("ignore_logs")
 
     def echo(message):
-        """Listen for messages and echo them for logging"""
+        global _log_all_bus_messages
         try:
-            js_msg = json.loads(message)
+            msg = json.loads(message)
 
-            if whitelist and js_msg.get("type") not in whitelist:
+            if whitelist and msg.get("type") not in whitelist:
                 return
 
-            if blacklist and js_msg.get("type") in blacklist:
+            if blacklist and msg.get("type") in blacklist:
                 return
 
-            if js_msg.get("type") == "registration":
+            if msg.get("type") == "mycroft.debug.log":
+                # Respond to requests to adjust the logger settings
+                lvl = msg["data"].get("level", "").upper()
+                if lvl in ["CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG"]:
+                    LOG(name).info("Changing log level to: "+lvl)
+                    LOG(name).setLevel(lvl)
+
+                # Allow enable/disable of messagebus traffic
+                log_bus = msg["data"].get("bus", None)
+                if not log_bus is None:
+                    LOG(name).info("Bus logging: "+str(log_bus))
+                    _log_all_bus_messages = log_bus
+            elif msg.get("type") == "registration":
                 # do not log tokens from registration messages
-                js_msg["data"]["token"] = None
+                msg["data"]["token"] = None
-                message = json.dumps(js_msg)
+                message = json.dumps(msg)
         except Exception:
             pass
-        LOG(name).debug(message)
+
+        if _log_all_bus_messages:
+            # Listen for messages and echo them for logging
+            LOG(name).debug(message)
     return echo