[logtools]: split lprint in elog_print (for elogbook) and std_print (for user)

bliss/common/axis.py

@@ -18,7 +18,7 @@ from bliss.common import event
 from bliss.common.greenlet_utils import protect_from_one_kill
 from bliss.common.utils import with_custom_members, safe_get
 from bliss.config.channels import Channel
-from bliss.common.logtools import log_debug, lprint, lprint_disable
+from bliss.common.logtools import log_debug, user_print
 from bliss.common.utils import rounder
 from bliss.common.utils import autocomplete_property
 
@@ -163,7 +163,7 @@ class GroupMove:
 
                 msg = motion_obj.user_msg
                 if msg:
-                    lprint(msg)
+                    user_print(msg)
 
         started = gevent.event.Event()
 
@@ -411,11 +411,11 @@ class GroupMove:
                     motion.axis._set_move_done()
 
             if self._interrupted_move:
-                lprint("")
+                user_print("")
                 for motion in motions:
                     _axis = motion.axis
                     _axis_pos = safe_get(_axis, "position", on_error="!ERR")
-                    lprint(f"Axis {_axis.name} stopped at position {_axis_pos}")
+                    user_print(f"Axis {_axis.name} stopped at position {_axis_pos}")
 
             try:
                 if self.parent:
@@ -1007,7 +1007,7 @@ class Axis:
         new_dial = float(new_dial)  # accepts both float or numpy array of 1 element
         old_dial = self.dial
         new_dial = self.__do_set_dial(new_dial)
-        lprint(f"'{self.name}` dial position reset from {old_dial} to {new_dial}")
+        user_print(f"'{self.name}` dial position reset from {old_dial} to {new_dial}")
 
     def __do_set_position(self, new_pos=None, offset=None):
         dial = self.dial
@@ -1061,7 +1061,7 @@ class Axis:
         if self.no_offset:
             self.dial = new_pos
         if self.__do_set_position(new_pos):
-            lprint(
+            user_print(
                 f"'{self.name}` position reset from {curr_pos} to {new_pos} (sign: {self.sign}, offset: {self.offset})"
             )
 

bliss/common/logtools.py

@@ -8,7 +8,7 @@
 import sys
 import logging
 import logging.handlers
-import contextlib
+from contextlib import contextmanager
 import re
 from fnmatch import fnmatch, fnmatchcase
 import networkx as nx
@@ -20,9 +20,6 @@ from bliss.common.mapping import format_node, map_id
 from bliss import global_map, current_session
 
 
-logbook_on = False
-
-
 __all__ = [
     "log_debug",
     "log_debug_data",
@@ -35,7 +32,7 @@ __all__ = [
     "hexify",
     "asciify",
     "get_logger",
-    "lprint",
+    "elog_print",
 ]
 
 
@@ -222,146 +219,307 @@ def set_log_format(instance, frmt):
         raise
 
 
-from logging import LoggerAdapter
-from logging import StreamHandler
+def elogbook_filter(record):
+    """Checks whether an electronic logbook is available.
+    """
+    if current_session:
+        return current_session.scan_saving.elogbook is not None
+    else:
+        # No active session -> no notion of data policy
+        return False
+
+
+class PrintFormatter(logging.Formatter):
+    """Adds the level name as a prefix for messages with WARNING level or higher.
+    """
+
+    def format(self, record):
+        msg = record.getMessage()
+        if not getattr(record, "msg_type", None) and record.levelno >= logging.WARNING:
+            msg = record.levelname + ": " + msg
+        return msg
 
 
-class LogbookAdapter(LoggerAdapter):
-    def process(self, msg, kwargs):
-        return msg + f",{self.extra['end']},{chr(self.extra['flush'])}", kwargs
+class PrintHandler(logging.Handler):
+    """Redirect log records to `print`. By default the output stream is
+    sys.stdout or sys.stderr depending on the error level.
+
+    Optional: to modify the default print arguments, you can add the
+    `print_kwargs` attribute to the log record.
+    """
+
+    _DEFAULT_PRINT_KWARGS = {"flush": True, "end": "\n", "file": None}
+
+    def __init__(self, *args, **kw):
+        super().__init__(*args, **kw)
+        self.setFormatter(PrintFormatter())
+
+    def emit(self, record):
+        msg = self.format(record)
+        kwargs = self._DEFAULT_PRINT_KWARGS.copy()
+        kwargs.update(getattr(record, "print_kwargs", {}))
+        if kwargs["file"] is None:
+            if record.levelno >= logging.WARNING:
+                kwargs["file"] = sys.stderr
+            else:
+                kwargs["file"] = sys.stdout
+        print(msg, **kwargs)
+
+
+class ElogHandler(logging.Handler):
+    """Redirect log records to the electronic logbook. The default message
+    type depends on the record's log level.
+
+    Optional: to overwrite the default message type, you add the `msg_type`
+    attribute to the log record.
+    """
 
+    _MSG_TYPES = {
+        logging.DEBUG: "debug",
+        logging.INFO: "info",
+        logging.WARNING: "warning",
+        logging.ERROR: "error",
+        logging.CRITICAL: "critical",
+    }
 
-class LogbookStdoutHandler(StreamHandler):
     def emit(self, record):
+        msg = self.format(record)
+        msg_type = getattr(record, "msg_type", None)
+        if not msg_type:
+            msg_type = self._MSG_TYPES.get(record.levelno, None)
+        try:
+            elogbook = current_session.scan_saving.elogbook
+            elogbook.send_message(msg, msg_type=msg_type)
+        except Exception as e:
+            log_error(self, f"Electronic logbook failed ({e})")
+
+
+class ForcedLogger(logging.Logger):
+    """Logger with an additional `forced_log` method which makes sure the message
+    is always send to the handlers, regardless of the level.
+    """
+
+    def forced_log(self, *args, **kw):
+        """Log with INFO level or higher to ensure the message is not filtered
+        out by the logger's log level. Note that the handler's log level may
+        still filter out the message for that particular handler.
         """
-        Emit a record.
-
-        If a formatter is specified, it is used to format the record.
-        The record is then written to the stream with a trailing newline.  If
-        exception information is present, it is formatted using
-        traceback.print_exception and appended to the stream.  If the stream
-        has an 'encoding' attribute, it is used to determine how to do the
-        output to the stream.
+        level = max(self.getEffectiveLevel(), logging.INFO)
+        self.log(level, *args, **kw)
+
+    def _set_msg_type(self, kw, msg_type):
+        """Add message type to the resulting record. Often useful before
+        calling `forced_log`.
         """
-        try:
-            msg = self.format(record)
-            stream = sys.stdout
-            msg, end, flush = msg.rsplit(",", maxsplit=2)
-            stream.write(msg)
-            if flush:
-                self.flush()
-            if end:
-                stream.write(end)
-            logbook_printer.send_to_elogbook("info", msg)
-        except (KeyboardInterrupt, SystemExit):
-            raise
-        except:
-            self.handleError(record)
-
-
-class LogbookPrint:
-    def __init__(self):
-        self.extra = {"flush": True, "end": "\n"}
-        self.logger = logging.getLogger("bliss.logbook_print")
-        self.adapter = LogbookAdapter(self.logger, self.extra)
-
-        self.logger.setLevel(logging.INFO)
-        self.logger.propagate = False
-
-        self.stdout_handler = LogbookStdoutHandler()
-        self.stdout_handler.setLevel(logging.INFO)
-
-        self.disabled = weakref.WeakKeyDictionary()
-
-    def add_stdout_handler(self):
-        """adding handler will prints to stdout lprint messages"""
-        if self.stdout_handler not in self.logger.handlers:
-
-            def filter_greenlet(record):
-                # filter greenlets
-                current = gevent.getcurrent()
-                while current:
-                    # looping parents greenlets
-                    # until we find a disabled one
-                    # or we arrive at root
-                    if current in self.disabled.keys():
-                        return False
-                    try:
-                        current = current.spawning_greenlet()
-                    except AttributeError:
-                        current = current.parent
-                return True
+        extra = kw.setdefault("extra", {})
+        if not extra.get("msg_type"):
+            extra["msg_type"] = msg_type
+
 
-            self.logger.addHandler(self.stdout_handler)
-            self.logger.addFilter(filter_greenlet)
+class PrintLogger(ForcedLogger):
+    """Logger with a `print` method which takes the same arguments as the
+    builtin `print`. It adds attribute `print_kwargs` to the log record.
+    """
 
-    def remove_stdout_handler(self):
-        if self.stdout_handler in self.logger.handlers:
-            self.logger.removeHandler(self.stdout_handler)
+    def print(self, *args, **kw):
+        """Always send to the handlers, regardless of the log level
+        """
+        sep = kw.get("sep", " ")
+        msg = sep.join((str(arg) for arg in args))
 
-    def has_stdout_handler(self):
-        return self.stdout_handler in self.logger.handlers
+        keys = ["file", "end", "flush", "sep"]  # built-in print API
+        extra = kw.get("extra", {})
+        extra["print_kwargs"] = {k: kw[k] for k in keys if k in kw}
 
-    def add_logbook_handler(self):
-        raise NotImplementedError
+        self._set_msg_type(kw, "print")
+        self.forced_log(msg, extra=extra)
 
-    def remove_logbook_handler(self):
-        raise NotImplementedError
 
-    def lprint(self, *args, **kwargs):
-        sep = kwargs.pop("sep", " ")
-        self.extra["end"] = kwargs.pop("end", "\n")
-        self.extra["flush"] = kwargs.pop("flush", True)
-        if len(args) > 1:
-            msg = sep.join((str(arg) for arg in args))
-        else:
-            msg = args[0]
-        self.adapter.info(msg)
+class ElogLogger(ForcedLogger):
+    """Logger with additional `comment` and `command` methods. These methods
+    add the attribute `msg_type` to the log record.
+
+    It also adds a filter for the `command` messages.
+    """
+
+    _IGNORED_COMMANDS = {"elog_print("}
+
+    def __init__(self, *args, **kw):
+        super().__init__(*args, **kw)
+        self.addFilter(self._command_filter)
+
+    @classmethod
+    def _command_filter(cls, record):
+        if getattr(record, "msg_type", None) == "command":
+            msg = record.getMessage()
+            if any(msg.startswith(s) for s in cls._IGNORED_COMMANDS):
+                return False
+        return True
+
+    @classmethod
+    def disable_command_logging(cls, method):
+        """Filter out the logging of this method.
 
-    @contextlib.contextmanager
-    def lprint_disable(self):
+        Args:
+            method (str or callable)
+
+        Returns:
+            str or callable: sane as `method`
+        """
+        command = method
+        if not isinstance(command, str):
+            command = command.__name__
+        cls._IGNORED_COMMANDS.add(command + "(")
+        return method
+
+    def comment(self, *args, **kw):
+        """User comment which can be modified later
+        """
+        self._set_msg_type(kw, "comment")
+        self.forced_log(*args, **kw)
+
+    def command(self, *args, **kw):
+        """Specific commands can be filtered out with `disable_command_logging`
+        """
+        self._set_msg_type(kw, "command")
+        self.forced_log(*args, **kw)
+
+
+class GreenletDisableLogger(logging.Logger):
+    """Logger which can be disabled for specific greenlets.
+    """
 
-        # lprint_disable keeps track of the current greenlet
+    def __init__(self, *args, **kw):
+        super().__init__(*args, **kw)
+        self.addFilter(self._greenlet_filter)
+        self.reset()
+
+    def reset(self):
+        """Enable all disabled greenlets
+        """
+        self._disabled_greenlets = weakref.WeakKeyDictionary()
+
+    def _greenlet_filter(self, record):
+        """Filter out this log record when the logging is disabled
+        for the current greenlet.
+        """
         current = gevent.getcurrent()
+        while current:
+            # looping parents greenlets
+            # until we find a disabled one
+            # or we arrive at root
+            if self._disabled_greenlets.get(current, 0) > 0:
+                return False
+            try:
+                current = current.spawning_greenlet()
+            except AttributeError:
+                current = current.parent
+        return True
+
+    @contextmanager
+    def disable_in_greenlet(self, greenlet=None):
+        """Disable logging in a greenlet within this context.
+        It takes the current greenlet by default.
+        """
+        # Increment the greenlet counter
+        if greenlet is None:
+            current = gevent.getcurrent()
         try:
-            # keeping track of nested levels of lprint_disable
-            self.disabled[current] += 1
+            self._disabled_greenlets[current] += 1
         except KeyError:
-            self.disabled[current] = 1
-
-        yield
+            self._disabled_greenlets[current] = 1
 
         try:
-            self.disabled[current] -= 1
-            if self.disabled[current] <= 0:
-                # when we exit the last `with` we can delete the reference
-                del (self.disabled[current])
-        except KeyError:
-            pass
+            yield
+        finally:
+            # Decrement the greenlet counter
+            try:
+                self._disabled_greenlets[current] -= 1
+                if self._disabled_greenlets[current] <= 0:
+                    del self._disabled_greenlets[current]
+            except KeyError:
+                pass
 
-    def send_to_elogbook(self, msg_type, msg):
-        if not logbook_on:
-            return
 
-        if current_session:
-            if current_session.scan_saving.data_policy != "ESRF":
-                return
-            if current_session.scan_saving.proposal_type == "tmp":
-                return
+class UserLogger(PrintLogger, GreenletDisableLogger):
+    """When enabled, log messages are visible to the user.
+    No message propagation to parent loggers.
 
-        try:
-            icat_proxy = current_session.scan_saving.icat_proxy
-            icat_proxy.send_to_elogbook(msg_type, msg)
-        except RuntimeError:
-            log_error(self, "elogbook: MetadataManager communication failed")
+    In addition to the standard logger methods we have:
+        print: use like the builtin `print` ("info" level or higher)
+        disable_in_greenlet: disable logging for a greenlet (current by default)
+    """
+
+    def __init__(self, _args, **kw):
+        super().__init__(_args, **kw)
+        self.propagate = False
+        self._null_handler = logging.NullHandler()
+        self._print_handler = PrintHandler()
+        self.disable()
+
+    def enable(self):
+        self.addHandler(self._print_handler)
+        self.removeHandler(self._null_handler)
+
+    def disable(self):
+        self.removeHandler(self._print_handler)
+        self.addHandler(self._null_handler)
+
+
+class Elogbook(PrintLogger, ElogLogger):
+    """When enabled, log messages are send to the electronic logbook.
+    No message propagation to parent loggers.
+
+    In addition to the standard logger methods we have:
+        comment: send a "comment" notification to the electronic logbook
+        command: send a "command" notification to the electronic logbook
+        print: use like the builtin `print` ("comment" notification)
+    """
+
+    def __init__(self, _args, **kw):
+        super().__init__(_args, **kw)
+        self.propagate = False
+        self._null_handler = logging.NullHandler()
+        self._elog_handler = ElogHandler()
+        self._elog_handler.addFilter(elogbook_filter)
+        self.disable()
+
+    def enable(self):
+        self.addHandler(self._elog_handler)
+        self.removeHandler(self._null_handler)
+
+    def disable(self):
+        self.removeHandler(self._elog_handler)
+        self.addHandler(self._null_handler)
+
+    def print(self, *args, **kw):
+        self._set_msg_type(kw, "comment")
+        super().print(*args, **kw)
+
+
+userlogger = UserLogger("bliss.userlogger", level=logging.NOTSET)
+
+user_print = userlogger.print
+user_debug = userlogger.debug
+user_info = userlogger.info
+user_warning = userlogger.warning
+user_error = userlogger.error
+user_critical = userlogger.critical
+disable_user_output = userlogger.disable_in_greenlet
 
+elogbook = Elogbook("bliss.elogbook", level=logging.NOTSET)
 
-logbook_printer = LogbookPrint()
-lprint = logbook_printer.lprint
-lprint_disable = logbook_printer.lprint_disable
+elog_print = elogbook.print  # exposed to the shell
+elog_debug = elogbook.debug
+elog_info = elogbook.info
+elog_warning = elogbook.warning
+elog_error = elogbook.error
+elog_critical = elogbook.critical
+elog_comment = elogbook.comment
+elog_command = elogbook.command
 
 
-@contextlib.contextmanager
+@contextmanager
 def bliss_logger():
     saved_logger_class = logging.getLoggerClass()
     logging.setLoggerClass(BlissLogger)

bliss/common/regulation.py

@@ -167,7 +167,7 @@ import enum
 
 from bliss import current_session
 from bliss import global_map
-from bliss.common.logtools import log_debug, lprint_disable
+from bliss.common.logtools import log_debug, disable_user_output
 from bliss.common.utils import with_custom_members, autocomplete_property
 from bliss.common.counter import SamplingCounter
 from bliss.controllers.counter import SamplingCounterController, counter_namespace
@@ -655,7 +655,7 @@ class ExternalOutput(Output):
         log_debug(self, "ExternalOutput:_set_value %s" % value)
 
         if isinstance(self.device, Axis):
-            with lprint_disable():
+            with disable_user_output():
                 if self.mode == "relative":
                     self.device.rmove(value)
                 elif self.mode == "absolute":

bliss/common/standard.py

@@ -26,7 +26,7 @@ from bliss.common.cleanup import cleanup, error_cleanup
 from bliss.common import cleanup as cleanup_mod
 from bliss.common import logtools
 from bliss.common.logtools import *
-from bliss.common.logtools import lprint
+from bliss.common.logtools import user_print, disable_user_output
 from bliss.common.interlocks import interlock_state
 from bliss.controllers.motors import esrf_undulator
 from bliss.config.channels import clear_cache
@@ -75,7 +75,7 @@ def sync(*axes):
         axes: list of axis objects or names. If no axis is given, it syncs all
               all axes present in the session
     """
-    lprint("Forcing axes synchronization with hardware")
+    user_print("Forcing axes synchronization with hardware")
     if axes:
         axes = global_map.get_axis_objects_iter(*axes)
     else:
@@ -363,7 +363,7 @@ def rockit(motor, total_move):
     motor._get_motion(upper_position)
 
     def rock():
-        with logtools.lprint_disable():
+        with disable_user_output():
             while True:
                 motor.move(lower_position)
                 motor.move(upper_position)

bliss/controllers/lima/properties.py

@@ -12,7 +12,7 @@ import re
 
 from bliss.common.tango import DevFailed
 from bliss.config.beacon_object import BeaconObject
-from bliss.common.standard import lprint
+from bliss.common.logtools import user_error
 
 LimaProperty = type("LimaProperty", (property,), {})
 
@@ -20,11 +20,9 @@ LimaProperty = type("LimaProperty", (property,), {})
 def LimaBeaconObjectProperty(name, lima_get, lima_convert_to_write):
     def fget(self):
         try:
-            ret = lima_get(self)
+            return lima_get(self)
         except DevFailed as exc:
-            lprint(f"Error reading {name}: {exc.args[0].desc.strip()}")
-        else:
-            return ret
+            user_error(f"reading lima property {name} ({exc.args[0].desc.strip()})")
 
     fget.__name__ = name
 

bliss/controllers/machinfo.py

@@ -11,7 +11,7 @@ from bliss import global_map
 from bliss.config.beacon_object import BeaconObject
 from bliss.common.scans import DEFAULT_CHAIN
 from bliss.common.user_status_info import status_message
-from bliss.common.standard import lprint
+from bliss.common.logtools import user_print
 
 from bliss.common import timedisplay
 from bliss.controllers.counter import counter_namespace
@@ -111,11 +111,11 @@ class MachInfo(BeaconObject):
             preset = WaitForRefillPreset(self)
             DEFAULT_CHAIN.add_preset(preset, name=self.KEY_NAME)
             self.__check = True
-            lprint("Activating Wait For Refill on scans")
+            user_print("Activating Wait For Refill on scans")
         else:
             DEFAULT_CHAIN.remove_preset(name=self.KEY_NAME)
             self.__check = False
-            lprint("Removing Wait For Refill on scans")
+            user_print("Removing Wait For Refill on scans")
 
     @BeaconObject.property(default=True)
     def metadata(self):

bliss/controllers/mca/xia.py

@@ -9,8 +9,7 @@
 
 # Imports
 from bliss import is_bliss_shell
-from bliss.common.logtools import log_debug
-from bliss.common.standard import lprint
+from bliss.common.logtools import log_debug, user_print
 from bliss.common import event
 from bliss.config.beacon_object import BeaconObject
 
@@ -199,7 +198,7 @@ class BaseXIA(BaseMCA):
         The filename is relative to the configuration directory.
         """
         try:
-            lprint(f"Loading configuration '{filename}'")
+            user_print(f"Loading configuration '{filename}'")
             self._proxy.init(self.beacon_obj.configuration_directory, filename)
             self._proxy.start_system()  # Takes about 5 seconds
             self._run_checks()

bliss/controllers/motors/esrf_undulator.py

@@ -12,7 +12,7 @@ import gevent