[writer] improve logging

nexus_writer_service/subscribers/base_subscriber.py

@@ -316,7 +316,7 @@ class BaseSubscriber(object):
                     timelimit=100,
                     memlimit=30,
                     sortby=["cumtime", "tottime"],
-                    color=True,
+                    color=False,
                     filename=dumpname,
                     units="MB",
                 ):

nexus_writer_service/tango/servers/NexusWriter.py

@@ -24,6 +24,7 @@ from tango.server import attribute, command
 from tango.server import device_property
 from tango import AttrQuality, DispLevel, DevState
 from tango import AttrWriteType, PipeWriteType
+import enum
 
 # Additional import
 # PROTECTED REGION ID(NexusWriter.additionnal_import) ENABLED START #
@@ -33,19 +34,10 @@ import re
 import os
 import itertools
 from tango import LogLevel
+import nexus_writer_service
 from nexus_writer_service.subscribers import session_writer
 from nexus_writer_service.subscribers.scan_writer_base import NexusScanWriterBase
-from nexus_writer_service.utils.log_levels import tango_log_level
-
-# Not sure why this keep showing output in info level
-def DebugIt():
-    def wrap(func):
-        return func
-
-    return wrap
-
-
-logger = logging.getLogger(__name__)
+from nexus_writer_service.utils import log_levels
 
 
 def session_tango_state(state):
@@ -103,11 +95,45 @@ def strftime(tm):
         return tm.strftime("%Y-%m-%d %H:%M:%S")
 
 
+read_log_level = {
+    logging.NOTSET: 0,
+    logging.DEBUG: 1,
+    logging.INFO: 2,
+    logging.WARNING: 3,
+    logging.ERROR: 4,
+    logging.CRITICAL: 5,
+}
+
+write_log_level = {v: k for k, v in read_log_level.items()}
+
+
 # PROTECTED REGION END #    //  NexusWriter.additionnal_import
 
 __all__ = ["NexusWriter", "main"]
 
 
+class Writer_log_level(enum.IntEnum):
+    """Python enumerated type for Writer_log_level attribute."""
+
+    NOTSET = 0
+    DEBUG = 1
+    INFO = 2
+    WARN = 3
+    ERROR = 4
+    FATAL = 5
+
+
+class Tango_log_level(enum.IntEnum):
+    """Python enumerated type for Tango_log_level attribute."""
+
+    NOTSET = 0
+    DEBUG = 1
+    INFO = 2
+    WARN = 3
+    ERROR = 4
+    FATAL = 5
+
+
 class NexusWriter(Device):
     """
 
@@ -183,6 +209,12 @@ class NexusWriter(Device):
 
     resource_profiling = attribute(dtype="DevBoolean", access=AttrWriteType.READ_WRITE)
 
+    writer_log_level = attribute(
+        dtype=Writer_log_level, access=AttrWriteType.READ_WRITE
+    )
+
+    tango_log_level = attribute(dtype=Tango_log_level, access=AttrWriteType.READ_WRITE)
+
     scan_states = attribute(dtype=("DevState",), max_dim_x=10000)
 
     scan_uris = attribute(dtype=("DevString",), max_dim_x=10000)
@@ -209,11 +241,8 @@ class NexusWriter(Device):
         """Initialises the attributes and properties of the NexusWriter."""
         Device.init_device(self)
         # PROTECTED REGION ID(NexusWriter.init_device) ENABLED START #
-        # TODO: Python logging respects the CLI argument -v but
-        #       the device log level is always DEBUG.
-        level = tango_log_level[logger.getEffectiveLevel()]
-        _logger = self.get_logger()
-        _logger.set_level(level)
+        level = nexus_writer_service.logger.getEffectiveLevel()
+        self.get_logger().set_level(log_levels.tango_log_level[level])
         self.session_writer = getattr(self, "session_writer", None)
         if self.session_writer is None:
             self.session_writer = session_writer.NexusSessionWriter(
@@ -254,6 +283,32 @@ class NexusWriter(Device):
         self.session_writer.resource_profiling = value
         # PROTECTED REGION END #    //  NexusWriter.resource_profiling_write
 
+    def read_writer_log_level(self):
+        # PROTECTED REGION ID(NexusWriter.writer_log_level_read) ENABLED START #
+        """Return the writer_log_level attribute."""
+        return read_log_level[nexus_writer_service.logger.getEffectiveLevel()]
+        # PROTECTED REGION END #    //  NexusWriter.writer_log_level_read
+
+    def write_writer_log_level(self, value):
+        # PROTECTED REGION ID(NexusWriter.writer_log_level_write) ENABLED START #
+        """Set the writer_log_level attribute."""
+        nexus_writer_service.logger.setLevel(write_log_level[value])
+        # PROTECTED REGION END #    //  NexusWriter.writer_log_level_write
+
+    def read_tango_log_level(self):
+        # PROTECTED REGION ID(NexusWriter.tango_log_level_read) ENABLED START #
+        """Return the tango_log_level attribute."""
+        return read_log_level[
+            log_levels.itango_log_level[self.get_logger().get_level()]
+        ]
+        # PROTECTED REGION END #    //  NexusWriter.tango_log_level_read
+
+    def write_tango_log_level(self, value):
+        # PROTECTED REGION ID(NexusWriter.tango_log_level_write) ENABLED START #
+        """Set the tango_log_level attribute."""
+        self.get_logger().set_level(log_levels.tango_log_level[write_log_level[value]])
+        # PROTECTED REGION END #    //  NexusWriter.tango_log_level_write
+
     def read_scan_states(self):
         # PROTECTED REGION ID(NexusWriter.scan_states_read) ENABLED START #
         """Return the scan_states attribute."""

nexus_writer_service/tango/servers/NexusWriter.xmi

@@ -169,6 +169,34 @@
       <status abstract="false" inherited="false" concrete="true" concreteHere="true"/>
       <properties description="" label="" unit="" standardUnit="" displayUnit="" format="" maxValue="" minValue="" maxAlarm="" minAlarm="" maxWarning="" minWarning="" deltaTime="" deltaValue=""/>
     </attributes>
+    <attributes name="writer_log_level" attType="Scalar" rwType="READ_WRITE" displayLevel="OPERATOR" polledPeriod="0" maxX="" maxY="" allocReadMember="true" isDynamic="false">
+      <dataType xsi:type="pogoDsl:EnumType"/>
+      <changeEvent fire="false" libCheckCriteria="false"/>
+      <archiveEvent fire="false" libCheckCriteria="false"/>
+      <dataReadyEvent fire="false" libCheckCriteria="true"/>
+      <status abstract="false" inherited="false" concrete="true" concreteHere="true"/>
+      <properties description="" label="" unit="" standardUnit="" displayUnit="" format="" maxValue="" minValue="" maxAlarm="" minAlarm="" maxWarning="" minWarning="" deltaTime="" deltaValue=""/>
+      <enumLabels>NOTSET</enumLabels>
+      <enumLabels>DEBUG</enumLabels>
+      <enumLabels>INFO</enumLabels>
+      <enumLabels>WARN</enumLabels>
+      <enumLabels>ERROR</enumLabels>
+      <enumLabels>FATAL</enumLabels>
+    </attributes>
+    <attributes name="tango_log_level" attType="Scalar" rwType="READ_WRITE" displayLevel="OPERATOR" polledPeriod="0" maxX="" maxY="" allocReadMember="true" isDynamic="false">
+      <dataType xsi:type="pogoDsl:EnumType"/>
+      <changeEvent fire="false" libCheckCriteria="false"/>
+      <archiveEvent fire="false" libCheckCriteria="false"/>
+      <dataReadyEvent fire="false" libCheckCriteria="true"/>
+      <status abstract="false" inherited="false" concrete="true" concreteHere="true"/>
+      <properties description="" label="" unit="" standardUnit="" displayUnit="" format="" maxValue="" minValue="" maxAlarm="" minAlarm="" maxWarning="" minWarning="" deltaTime="" deltaValue=""/>
+      <enumLabels>NOTSET</enumLabels>
+      <enumLabels>DEBUG</enumLabels>
+      <enumLabels>INFO</enumLabels>
+      <enumLabels>WARN</enumLabels>
+      <enumLabels>ERROR</enumLabels>
+      <enumLabels>FATAL</enumLabels>
+    </attributes>
     <attributes name="scan_states" attType="Spectrum" rwType="READ" displayLevel="OPERATOR" polledPeriod="0" maxX="10000" maxY="" allocReadMember="true" isDynamic="false">
       <dataType xsi:type="pogoDsl:StateType"/>
       <changeEvent fire="false" libCheckCriteria="false"/>

nexus_writer_service/utils/log_levels.py

 import logging
 from tango import LogLevel
 
+# tango_log_level = {
+#    logging.DEBUG: LogLevel.LOG_DEBUG,
+#    logging.INFO: LogLevel.LOG_INFO,
+#    logging.WARNING: LogLevel.LOG_WARN,
+#    logging.ERROR: LogLevel.LOG_ERROR,
+#    logging.CRITICAL: LogLevel.LOG_FATAL,
+#    logging.NOTSET: LogLevel.LOG_OFF,
+# }
+
 tango_log_level = {
-    logging.DEBUG: LogLevel.LOG_DEBUG,
-    logging.INFO: LogLevel.LOG_INFO,
-    logging.WARNING: LogLevel.LOG_WARN,
-    logging.ERROR: LogLevel.LOG_ERROR,
-    logging.CRITICAL: LogLevel.LOG_FATAL,
-    logging.NOTSET: LogLevel.LOG_OFF,
+    logging.DEBUG: 600,
+    logging.INFO: 500,
+    logging.WARNING: 400,
+    logging.ERROR: 300,
+    logging.CRITICAL: 200,
+    logging.NOTSET: 100,
 }
 
+itango_log_level = {v: k for k, v in tango_log_level.items()}
+
 tango_cli_log_level = {
     logging.DEBUG: 5,
     logging.INFO: 4,
@@ -19,6 +30,7 @@ tango_cli_log_level = {
     logging.NOTSET: 0,
 }
 
+itango_cli_log_level = {v: k for k, v in tango_cli_log_level.items()}
 
 beacon_log_level = {
     logging.DEBUG: "DEBUG",
@@ -29,6 +41,7 @@ beacon_log_level = {
     logging.NOTSET: "WARN",
 }
 
+ibeacon_log_level = {v: k for k, v in beacon_log_level.items()}
 
 log_level_name = {
     logging.DEBUG: "DEBUG",
@@ -38,3 +51,5 @@ log_level_name = {
     logging.CRITICAL: "CRITICAL",
     logging.NOTSET: "NOTSET",
 }
+
+ilog_level_name = {v: k for k, v in log_level_name.items()}

nexus_writer_service/utils/logging_utils.py

@@ -212,6 +212,9 @@ def cliconfig(logger, default="WARNING", help=False):
     config(logger, **kwargs)
 
 
+DEFAULT_FORMAT = "%(levelname)s %(asctime)s %(name)s: %(message)s"
+
+
 def config(
     logger,
     level=None,
@@ -242,7 +245,7 @@ def config(
         "terminator": True,
         "filter_func": None,
         "formatter": True,
-        "fmt": "%(levelname)s:%(name)s: %(message)s",
+        "fmt": DEFAULT_FORMAT,
     }
 
     # - all messages to ...
@@ -352,11 +355,7 @@ def add_filehandler(
 
 
 def _add_outputhandler(
-    logger,
-    outputhandler,
-    formatter=False,
-    filter_func=None,
-    fmt="%(levelname)s:%(name)s: %(message)s",
+    logger, outputhandler, formatter=False, filter_func=None, fmt=DEFAULT_FORMAT
 ):
     """Direct logger output to an output handler
     """
@@ -367,10 +366,10 @@ def _add_outputhandler(
     logger.addHandler(outputhandler)
 
 
-def _add_formatting(outputhandler, fmt="%(levelname)s:%(name)s: %(message)s"):
+def _add_formatting(outputhandler, fmt=DEFAULT_FORMAT):
     """Define format of the logger output
     """
-    formatter = logging.Formatter(fmt)
+    formatter = logging.Formatter(fmt, "%Y-%m-%d %H:%M:%S")
     outputhandler.setFormatter(formatter)
 
 

tests/nexus_writer/test_logging.py

@@ -6,6 +6,7 @@
 # Distributed under the GNU LGPLv3. See LICENSE for more info.
 
 import os
+import re
 import subprocess
 import pprint
 import difflib
@@ -261,6 +262,9 @@ def validate_output(tmpdir, output, outtype, **kwargs):
     lines = lines.format(*args)
     lines = lines.split(os.linesep)
     output = output.split(os.linesep)
+    timestamp = r" \d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} "
+    output = [re.sub(timestamp, ":", s) for s in output]
+
     if lines != output:
         cmd = " ".join(cliargs(tmpdir, **kwargs))
         errmsg = "Unexpected {}".format(repr(outtype))