Merge branch 'logging_fix' into 'master'

Logging fix

Closes #755 and #762

See merge request bliss/bliss!1300

bliss/common/logtools.py

@@ -17,6 +17,17 @@ from bliss.common.mapping import _BEAMLINE_MAP, BEAMLINE_GRAPH, format_node
 __all__ = ["log", "lslog", "lsdebug"]
 
 
+def logging_startup(
+    log_level=logging.DEBUG, fmt="%(levelname)s %(asctime)-15s %(name)s: %(message)s"
+):
+    """
+    Provides basicConfig functionality to bliss activating at proper level the root loggers
+    """
+    logging.basicConfig(level=log_level, format=fmt)
+    logging.getLogger("bliss").setLevel(log_level)
+    logging.getLogger("beamline").setLevel(log_level)
+
+
 class LogMixin:
     @autocomplete_property
     def _logger(self, *args, **kwargs):
@@ -113,12 +124,13 @@ def improve_logger(logger_instance):
         """
 
         def __hex_format(ch):
+            if isinstance(ch, int):
+                # given a byte
+                return "\\x%02x" % ch
+            # given a string of one char
             return "\\x%02x" % ord(ch)
 
-        try:
-            return "".join(map(__hex_format, instr))
-        except:
-            return instr
+        return "".join(map(__hex_format, instr))
 
     # Appending methods to decorated class
     logger_instance.debugon = types.MethodType(debugon, logger_instance)
@@ -219,15 +231,17 @@ class Log:
         ]
         return sorted(filtered_loggers)
 
-    def _find_map_logger_by_name(self, name):
+    def _find_map_logger_by_name(self, glob):
         loggers = self._get_map_loggers()
-        findlog = [logname for logname, _, _ in loggers if logname.find(name) != -1]
+        findlog = [logname for logname, _, _ in loggers if fnmatchcase(logname, glob)]
+        # findlog = [logname for logname, _, _ in loggers if logname.find(name) != -1]
         findlog.sort()
         return findlog
 
-    def _find_bliss_logger_by_name(self, name):
+    def _find_bliss_logger_by_name(self, glob):
         loggers = self._get_bliss_loggers()
-        findlog = [logname for logname, _, _ in loggers if logname.find(name) != -1]
+        findlog = [logname for logname, _, _ in loggers if fnmatchcase(logname, glob)]
+        # findlog = [logname for logname, _, _ in loggers if logname.find(name) != -1]
         findlog.sort()
         return findlog
 
@@ -240,26 +254,32 @@ class Log:
         # return str(name).lower()
         return name
 
-    def debugon(self, name: str):
+    def debugon(self, glob: str) -> None:
         """
         Activates debug-level logging for a specifig logger
 
         Args:
-            name: The name of the logger
+            glob: glob style pattern matching
+
+        Hints on glob: pattern matching normally used by shells
+                       common operators are * for any number of characters
+                       and ? for one character of any type
 
         Returns:
             None
 
         Examples:
-            >>> log = Log()
-            >>> log.debugon('motorsrv')
+            >>> log.debugon('*motorsrv')
             Set logger [motorsrv] to DEBUG level
             Set logger [motorsrv.Connection] to DEBUG level
+            >>> log.debugon('*rob?')
+            Set logger [session.device.controller.roby] to DEBUG level
+            Set logger [session.device.controller.robz] to DEBUG level
         """
-        strname = self._check_log_name(name)
+        strname = self._check_log_name(glob)
         loggers = self._find_bliss_logger_by_name(strname)
         if not len(loggers):
-            print("NO bliss loggers found for [{0}]".format(name))
+            print("NO bliss loggers found for [{0}]".format(glob))
         else:
             for logname in loggers:
                 print("Set logger [{0}] to {1} level".format(logname, "DEBUG"))
@@ -267,23 +287,27 @@ class Log:
 
         loggers = self._find_map_logger_by_name(strname)
         if not len(loggers):
-            print("NO map loggers found for [{0}]".format(name))
+            print("NO map loggers found for [{0}]".format(glob))
         else:
             for logname in loggers:
                 print("Set logger [{0}] to {1} level".format(logname, "DEBUG"))
                 logging.getLogger(logname).setLevel(logging.DEBUG)
 
-    def debugoff(self, name: str) -> None:
+    def debugoff(self, glob: str) -> None:
         """
         Sets the debug level of the specified logger to INFO
 
         Args:
-            name: name of the logger
+            glob: glob style pattern matching
+
+        Hints on glob: pattern matching normally used by shells
+                       common operators are * for any number of characters
+                       and ? for one character of any type
         """
-        strname = self._check_log_name(name)
+        strname = self._check_log_name(glob)
         loggers = self._find_bliss_logger_by_name(strname)
         if not len(loggers):
-            print("NO bliss loggers found for [{0}]".format(strname))
+            print("NO bliss loggers found for [{0}]".format(glob))
         else:
             for logname in loggers:
                 print(
@@ -293,7 +317,7 @@ class Log:
 
         loggers = self._find_map_logger_by_name(strname)
         if not len(loggers):
-            print("NO map loggers found for [{0}]".format(name))
+            print("NO map loggers found for [{0}]".format(glob))
         else:
             for logname in loggers:
                 print("Remove {0} level from map logger [{1}]".format("DEBUG", logname))
@@ -398,6 +422,10 @@ class Log:
                    for example logging.ERROR or logging.INFO
             inherited: False to visualize only loggers that are not
                        inheriting the level from ancestors
+
+        Hints on glob: pattern matching normally used by shells
+                       common operators are * for any number of characters
+                       and ? for one character of any type
         Examples:
 
             >>> lslog()  # prints all loggers

bliss/common/motor_settings.py

@@ -148,6 +148,9 @@ class AxisSettings:
         """
         Remove cache for specified setting
         """
+        if setting_name == "position":
+            self.disable_cache("dial_position", flag)
+
         disabled_settings = self.__axis.controller.axis_settings.disabled_settings.setdefault(
             self.__axis, set()
         )

bliss/controllers/motors/mockup.py

@@ -95,6 +95,7 @@ class Mockup(Controller):
     """
 
     def initialize_axis(self, axis):
+        self._logger.debug(f"initializing axis {axis.name}")
         self._axis_moves[axis] = {"motion": None}
 
         if self.read_hw_position(axis) is None:
@@ -141,6 +142,7 @@ class Mockup(Controller):
         return motion
 
     def set_hw_limits(self, axis, low_limit, high_limit):
+        self._logger.debug(f"set axis limit low={low_limit}, high={high_limit}")
         if low_limit is None:
             low_limit = float("-inf")
         if high_limit is None:
@@ -162,6 +164,7 @@ class Mockup(Controller):
 
     def start_one(self, motion, t0=None):
         axis = motion.axis
+        self._logger.debug(f"moving {axis.name} to {motion.target_pos}")
         if self._get_axis_motion(axis):
             raise RuntimeError("Cannot start motion. Motion already in place")
         pos = self.read_position(axis)
@@ -196,6 +199,7 @@ class Mockup(Controller):
             pos = self.read_hw_position(axis)
         else:
             pos = motion.trajectory.position(t)
+        self._logger.debug(f"{axis.name} position is {pos}")
         return int(round(pos))
 
     def read_encoder(self, encoder):

bliss/shell/cli/main.py

@@ -6,7 +6,7 @@
 # Distributed under the GNU LGPLv3. See LICENSE for more info.
 
 """
- 
+
 Usage: bliss [-l | --log-level=<log_level>] [-s <name> | --session=<name>] [--no-tmux]
        bliss [-v | --version]
        bliss [-c <name> | --create=<name>]
@@ -33,14 +33,15 @@ warnings.filterwarnings("ignore", module="jinja2")
 
 import os
 import sys
-import logging
 import subprocess
 from docopt import docopt, DocoptExit
+import logging
 
 from bliss import release
 from bliss.config import static
 from bliss.config.static import Node
 from bliss.config.conductor import client
+from bliss.common.logtools import logging_startup
 
 from .repl import embed
 from . import session_files_templates as sft
@@ -172,11 +173,9 @@ def main():
         print("")
         arguments = docopt(__doc__)
 
-    # log level
+    # initialize logging
     log_level = getattr(logging, arguments["--log-level"][0].upper())
-    fmt = "%(levelname)s %(asctime)-15s %(name)s: %(message)s"
-    logging.basicConfig(level=log_level, format=fmt)
-    logging.getLogger("bliss").setLevel(log_level)
+    logging_startup(log_level)
 
     # Print version
     if arguments["--version"]:
@@ -276,6 +275,7 @@ def main():
                     "-m",
                     "bliss.shell.cli.start_bliss_repl",
                     session,
+                    arguments["--log-level"][0],
                 ]
             )
             ans = subprocess.run(

bliss/shell/cli/repl.py

@@ -15,6 +15,7 @@ import functools
 import traceback
 import gevent
 import time
+import logging
 
 from ptpython.repl import PythonRepl
 
@@ -34,6 +35,7 @@ from bliss.scanning.scan import set_scan_watch_callbacks
 from .prompt import BlissPrompt
 from .typing_helper import TypingHelper
 
+logger = logging.getLogger(__name__)
 
 # don't patch the event loop on windows
 if not is_windows():
@@ -484,6 +486,7 @@ def embed(*args, **kwargs):
         while True:
             try:
                 inp = cmd_line_i.app.run()
+                logger.debug(f"USER INPUT: {inp}")
                 cmd_line_i._execute(inp)
             except KeyboardInterrupt:
                 cmd_line_i.default_buffer.reset()

bliss/shell/cli/start_bliss_repl.py

@@ -8,10 +8,17 @@
 
 import sys
 from bliss.shell.cli.repl import embed
+from bliss.common.logtools import logging_startup
+import logging
 
 
 def main():
     session_name = sys.argv[1]
+
+    # initialize logging
+    log_level = getattr(logging, sys.argv[2].upper())
+    logging_startup(log_level)
+
     embed(session_name=session_name, use_tmux=True)
 
 

tests/motors/test_axis.py

@@ -630,6 +630,8 @@ def test_axis_disable_cache_settings_from_config(beacon):
     mot1_state = m1.state  # init
     mot1_position = m1.position
     mot2_state = m2.state  # init
+    # initialize position
+    m2.position
 
     # test no cache on both motors
     with mock.patch.object(m1.controller, "state") as new_state: