diff --git a/devices/common/lofar_git.py b/devices/common/lofar_git.py
index 353748d985ccf72483792456cbcd8a0a5aa1056b..f4f6217280fe612fa2e9a7830c1f026c1e36a815 100644
--- a/devices/common/lofar_git.py
+++ b/devices/common/lofar_git.py
@@ -2,7 +2,7 @@ import git # pip3 install gitpython
import os
from functools import lru_cache
-def get_repo(starting_directory: str = os.path.dirname(__file__)) -> git.Repo:
+def get_repo(starting_directory: str = os.path.dirname(os.path.abspath(__file__))) -> git.Repo:
""" Try finding the repository by traversing up the tree.
By default, the repository containing this module is returned.
@@ -50,14 +50,20 @@ def get_version(repo: git.Repo = None) -> str:
if repo is None:
repo = get_repo()
- branch = repo.active_branch
commit = repo.commit()
tags = {tag.commit: tag for tag in repo.tags}
if commit in tags:
+ # a tag = production ready
commit_str = "{}".format(tags[commit])
production_ready = True
+ elif repo.head.is_detached:
+ # no active branch
+ commit_str = "<detached HEAD> [{}]".format(commit)
+ production_ready = False
else:
+ # HEAD of a branch
+ branch = repo.active_branch
commit_str = "{} [{}]".format(branch, commit)
production_ready = False
diff --git a/devices/common/lofar_logging.py b/devices/common/lofar_logging.py
index d84a47467caf860c2839d3ac28752400ca3b2533..b0e1c2ac4d23d67522cbc984280015fa18a042b6 100644
--- a/devices/common/lofar_logging.py
+++ b/devices/common/lofar_logging.py
@@ -1,17 +1,87 @@
import logging
from functools import wraps
+from tango.server import Device
import sys
-
-# Always also log the hostname because it makes the origin of the log clear.
+import traceback
import socket
-hostname = socket.gethostname()
-def configure_logger(logger: logging.Logger, log_extra=None):
+from .lofar_git import get_version
+
+class TangoLoggingHandler(logging.Handler):
+ level_to_device_stream = {
+ logging.DEBUG: Device.debug_stream,
+ logging.INFO: Device.info_stream,
+ logging.WARN: Device.warn_stream,
+ logging.ERROR: Device.error_stream,
+ logging.FATAL: Device.fatal_stream,
+ }
+
+ def emit(self, record):
+ try:
+ if record.tango_device is None:
+ # log record is not related to any device
+ return
+ except AttributeError:
+ # log record is not annotated with a tango_device
+ return
+
+ # determine which log stream to use
+ stream = self.level_to_device_stream[record.levelno]
+
+ # send the log message to Tango
+ stream(record.tango_device, record.msg, *record.args)
+
+ self.flush()
+
+class LogAnnotator(logging.Formatter):
+ """ Annotates log records with:
+
+ record.tango_device: the Tango Device that is executing. """
+
+ @staticmethod
+ def get_current_tango_device() -> Device:
+ """ Return the tango Device we're currently executing for, or None if it can't be detected.
+
+ This is derived by traversing the stack and find a Device as 'self'. In some cases,
+ this fails, for example if a separate Thread is started for a certain Device. """
+
+ for frame,lineno in traceback.walk_stack(f=None):
+ if "self" in frame.f_locals and isinstance(frame.f_locals["self"], Device):
+ return frame.f_locals["self"]
+
+ return None
+
+ def filter(self, record):
+ # annotate record with currently executing Tango device, if any
+ record.tango_device = self.get_current_tango_device()
+
+ # annotate record with the current software version
+ record.software_version = get_version()
+
+ # we just annotate, we don't filter
+ return True
+
+def configure_logger(logger: logging.Logger=None, log_extra=None):
+ """
+ Configure the given logger (or root if None) to:
+ - send logs to the ELK stack
+ - send logs to Tango
+ - send logs to stdout
+ """
+
+ # NOTE: We have to attach filters to handlers, instead to this logger,
+ # in order to have the filters be applied to descendent loggers.
+
+ if logger is None:
+ logger = logging.getLogger()
+
+ # By default we want to know everything
logger.setLevel(logging.DEBUG)
# remove spam from the OPC-UA client connection
logging.getLogger("opcua").setLevel(logging.WARN)
+ # Log to ELK stack
try:
from logstash_async.handler import AsynchronousLogstashHandler, LogstashFormatter
@@ -21,32 +91,52 @@ def configure_logger(logger: logging.Logger, log_extra=None):
# configure log messages
formatter = LogstashFormatter(extra=log_extra, tags=["python", "lofar"])
handler.setFormatter(formatter)
+ handler.addFilter(LogAnnotator())
# install the handler
logger.addHandler(handler)
+ except ImportError:
+ logger.exception("Cannot forward logs to ELK: logstash_async module not found.")
+ except Exception:
+ logger.exception("Cannot forward logs to ELK.")
- # for now, also log to stderr
- # Set up logging in a way that it can be understood by a human reader, be
- # easily grep'ed, be parsed with a couple of shell commands and
- # easily fed into an Kibana/Elastic search system.
- handler = logging.StreamHandler()
- formatter = logging.Formatter(fmt = '%(asctime)s.%(msecs)d %(levelname)s - HOST="{}" PID="%(process)d" TNAME="%(threadName)s" TID="%(thread)d" LOGGER="%(name)s" FILE="%(pathname)s" LINE="%(lineno)d" FUNC="%(funcName)s" MSG="%(message)s"'.format(hostname), datefmt = '%Y-%m-%dT%H:%M:%S')
- handler.setFormatter(formatter)
+ # Log to Tango
+ try:
+ handler = TangoLoggingHandler()
+ handler.addFilter(LogAnnotator())
logger.addHandler(handler)
except Exception:
- logger.exception("Cannot import or configure logstash_async module, not forwarding logs to ELK stack.")
+ logger.exception("Cannot forward logs to Tango.")
+
+
+ # for now, also log to stderr
+ # Set up logging in a way that it can be understood by a human reader, be
+ # easily grep'ed, be parsed with a couple of shell commands and
+ # easily fed into an Kibana/Elastic search system.
+ handler = logging.StreamHandler()
+
+ # Always also log the hostname because it makes the origin of the log clear.
+ hostname = socket.gethostname()
+
+ formatter = logging.Formatter(fmt = '%(asctime)s.%(msecs)d %(levelname)s - HOST="{}" DEVICE="%(tango_device)s" PID="%(process)d" TNAME="%(threadName)s" FILE="%(pathname)s" LINE="%(lineno)d" FUNC="%(funcName)s" MSG="%(message)s"'.format(hostname), datefmt = '%Y-%m-%dT%H:%M:%S')
+ handler.setFormatter(formatter)
+ handler.addFilter(LogAnnotator())
+
+ logger.addHandler(handler)
return logger
-def device_logging_to_python(log_extra: dict = None):
- """ Call this on a Tango Device instance or class to have your Tango Device log to python instead. """
+def device_logging_to_python():
+ """ Decorator. Call this on a Tango Device instance or class to have your Tango Device log to python instead. """
def inner(cls):
- # Create a logger that logs to ELK, dedicated for this class
- logger = logging.getLogger(cls.__name__)
- configure_logger(logger, log_extra)
+ # we'll be doing very weird things if this class isnt
+ if not issubclass(cls, Device):
+ raise ValueError("device_logging_to_python decorator is to be used on Tango Device classes only.")
# Monkey patch the python logger to replace the tango logger
+ logger = logging.getLogger()
+
cls.debug_stream = logger.debug
cls.info_stream = logger.info
cls.warn_stream = logger.warning
@@ -54,11 +144,12 @@ def device_logging_to_python(log_extra: dict = None):
cls.error_stream = logger.error
cls.fatal_stream = logger.fatal
cls.critical_stream = logger.critical
+
return cls
return inner
-def log_exceptions():
+def log_exceptions(logger: logging.Logger=None):
""" Decorator that logs all exceptions that the function raises. """
def wrapper(func):
@@ -67,8 +158,10 @@ def log_exceptions():
try:
return func(self, *args, **kwargs)
except Exception as e:
- self.error_stream("Unhandled exception: {}".format(e))
- raise e
+ (logger or logging.getLogger()).exception("Unhandled exception: %s: %s", e.__class__.__name__, e)
+
+ # we can log but we cannot hide
+ raise
return inner
diff --git a/devices/devices/apsctl.py b/devices/devices/apsctl.py
index 25d8e1080e5ce71a05634fee392aa9eff57ef711..b555cb1b68ac5f76261c73d9723aa050316dc9d8 100644
--- a/devices/devices/apsctl.py
+++ b/devices/devices/apsctl.py
@@ -34,7 +34,7 @@ import numpy
__all__ = ["APSCTL", "main"]
-@device_logging_to_python({"device": "APSCTL"})
+@device_logging_to_python()
class APSCTL(hardware_device):
"""
@@ -195,8 +195,7 @@ def main(args=None, **kwargs):
"""Main function of the SDP module."""
from devices.common.lofar_logging import configure_logger
- import logging
- configure_logger(logging.getLogger())
+ configure_logger()
return run((APSCTL,), args=args, **kwargs)
diff --git a/devices/devices/pcc.py b/devices/devices/pcc.py
index f21bd39a26405e323a7842718f571626f498cd5e..0db21b41e7c609c934345e0b0dafdea9e9e08efb 100644
--- a/devices/devices/pcc.py
+++ b/devices/devices/pcc.py
@@ -35,7 +35,7 @@ from common.lofar_git import get_version
__all__ = ["PCC", "main"]
-@device_logging_to_python({"device": "PCC"})
+@device_logging_to_python()
class PCC(hardware_device):
"""
@@ -251,8 +251,7 @@ def main(args=None, **kwargs):
"""Main function of the PCC module."""
from common.lofar_logging import configure_logger
- import logging
- configure_logger(logging.getLogger())
+ configure_logger()
return run((PCC,), args=args, **kwargs)
diff --git a/devices/devices/sdp/sdp.py b/devices/devices/sdp/sdp.py
index 24e22bf1e8ae8b2f3b5d38265f79dcfb451ebcd8..c78c1d042fae448adac4b9e24901a053f1683fe1 100644
--- a/devices/devices/sdp/sdp.py
+++ b/devices/devices/sdp/sdp.py
@@ -35,7 +35,7 @@ import numpy
__all__ = ["SDP", "main"]
-@device_logging_to_python({"device": "SDP"})
+@device_logging_to_python()
class SDP(hardware_device):
"""
@@ -174,8 +174,7 @@ def main(args=None, **kwargs):
"""Main function of the SDP module."""
from common.lofar_logging import configure_logger
- import logging
- configure_logger(logging.getLogger())
+ configure_logger()
return run((SDP,), args=args, **kwargs)
diff --git a/devices/devices/sdp/sst.py b/devices/devices/sdp/sst.py
index 3961362e916e044cfa833e9929856a0c25493a85..14b9e4ba381fc195f2d3c9997e51530e83e7e048 100644
--- a/devices/devices/sdp/sst.py
+++ b/devices/devices/sdp/sst.py
@@ -37,7 +37,7 @@ import numpy
__all__ = ["SST", "main"]
-@device_logging_to_python({"device": "SST"})
+@device_logging_to_python()
class SST(hardware_device):
# -----------------
@@ -174,8 +174,7 @@ def main(args=None, **kwargs):
"""Main function of the SST Device module."""
from common.lofar_logging import configure_logger
- import logging
- configure_logger(logging.getLogger())
+ configure_logger()
return run((SST,), args=args, **kwargs)
diff --git a/devices/test/util/__init__.py b/devices/test/common/__init__.py
similarity index 100%
rename from devices/test/util/__init__.py
rename to devices/test/common/__init__.py
diff --git a/devices/test/util/test_lofar_git.py b/devices/test/common/test_lofar_git.py
similarity index 90%
rename from devices/test/util/test_lofar_git.py
rename to devices/test/common/test_lofar_git.py
index 178eac535d52dfc6a2edf393a80e3c699e37a8b7..52a1c7d876fc2827757f082e0f44a0a64b1ffc78 100644
--- a/devices/test/util/test_lofar_git.py
+++ b/devices/test/common/test_lofar_git.py
@@ -35,9 +35,11 @@ class TestLofarGit(base.TestCase):
m_is_dirty = mock.Mock()
m_is_dirty.return_value = True
+ m_head = mock.Mock(is_detached=False)
+
m_get_repo.return_value = mock.Mock(
active_branch="main", commit=m_commit, tags=[],
- is_dirty=m_is_dirty)
+ is_dirty=m_is_dirty, head=m_head)
# No need for special string equal in Python
self.assertEqual("*main [123456]", lofar_git.get_version())
@@ -52,12 +54,14 @@ class TestLofarGit(base.TestCase):
m_is_dirty = mock.Mock()
m_is_dirty.return_value = False
+ m_head = mock.Mock(is_detached=False)
+
m_tag = mock.Mock(commit="123456")
m_tag.__str__ = mock.Mock(return_value= "version-1.2")
m_get_repo.return_value = mock.Mock(
active_branch="main", commit=m_commit,
- tags=[m_tag], is_dirty=m_is_dirty)
+ tags=[m_tag], is_dirty=m_is_dirty, head=m_head)
self.assertEqual("version-1.2", lofar_git.get_version())
@@ -71,13 +75,15 @@ class TestLofarGit(base.TestCase):
m_is_dirty = mock.Mock()
m_is_dirty.return_value = False
+ m_head = mock.Mock(is_detached=False)
+
m_tag = mock.Mock(commit="123456")
m_tag.__str__ = mock.Mock(return_value= "version-1.2")
# Now m_get_repo is mocked using a decorator
m_get_repo.return_value = mock.Mock(
active_branch="main", commit=m_commit,
- tags=[m_tag], is_dirty=m_is_dirty)
+ tags=[m_tag], is_dirty=m_is_dirty, head=m_head)
self.assertEqual("version-1.2", lofar_git.get_version())
diff --git a/devices/test/common/test_lofar_logging.py b/devices/test/common/test_lofar_logging.py
new file mode 100644
index 0000000000000000000000000000000000000000..534b2650c8d432ef7c7dae9e32448b01cc5913f3
--- /dev/null
+++ b/devices/test/common/test_lofar_logging.py
@@ -0,0 +1,105 @@
+# -*- coding: utf-8 -*-
+#
+# This file is part of the LOFAR 2.0 Station Software
+#
+#
+#
+# Distributed under the terms of the APACHE license.
+# See LICENSE.txt for more info.
+
+import git
+from unittest import mock
+
+from common import lofar_logging
+import logging
+from tango.server import Device
+from tango import device_server
+
+from test import base
+
+
+class TestLofarLogging(base.TestCase):
+
+
+ def setUp(self):
+ super(TestLofarLogging, self).setUp()
+
+
+ # reset logging system
+ rootLogger = logging.getLogger()
+ rootLogger.filters = []
+ rootLogger.handlers = []
+ rootLogger.manager.loggerDict = {}
+
+ # record everything we log in memory so we can inspect it
+ class MemoryHandler(logging.Handler):
+ """ Handler that provides access to the records emitted. """
+
+ def __init__(self):
+ super().__init__()
+ self.records = []
+
+ def emit(self, record):
+ self.records.append(record)
+
+ self.memory_handler = MemoryHandler()
+ rootLogger.addHandler(self.memory_handler)
+
+
+ def test_configure_logging_basic_usage(self):
+ """ Test whether configure_logger indeed runs smoothly. """
+
+ logger = lofar_logging.configure_logger()
+
+ logger.debug("test debug")
+ logger.info("test info")
+ logger.warning("test warning")
+ logger.error("test error")
+ logger.fatal("test fatal")
+
+
+ def test_configure_logging_log_annotation(self):
+ """ Test whether log records get annotated after using configure_logger(). """
+
+ logger = lofar_logging.configure_logger()
+
+ logger.info("test")
+ self.assertIn("tango_device", self.memory_handler.records[0].__dict__)
+ self.assertIn("software_version", self.memory_handler.records[0].__dict__)
+
+
+ def test_configure_logging_uses_tango_device(self):
+ """ Test whether log records get annotated with the active Tango device after using configure_logger(), and whether logs get forwarded to it. """
+
+ logger = lofar_logging.configure_logger()
+
+ # create a Tango Device that logs something
+ class MyDevice(Device):
+ def __init__(self):
+ self.log_deeper_in_stack()
+
+ def log_deeper_in_stack(self):
+ logger.info("test")
+
+ with mock.patch.object(device_server.DeviceImpl, '__info_stream') as m_info_stream:
+ # logs in the constructor already
+ mydevice = MyDevice()
+
+ self.assertEqual(mydevice, self.memory_handler.records[0].tango_device, msg="configure_logging did not detect active Tango device")
+ self.assertEqual(1, m_info_stream.call_count, msg="configure_logger did not send logs to active Tango device")
+
+
+ def test_log_exceptions(self):
+ """ Test whether log_exceptions actually logs and reraises exceptions. """
+
+ class Foo:
+ @lofar_logging.log_exceptions()
+ def exceptionalFunction(self):
+ raise Exception("test")
+
+ with self.assertRaises(Exception, msg="log_exceptions did not reraise exception"):
+ f = Foo()
+ f.exceptionalFunction()
+
+ self.assertEqual(1, len(self.memory_handler.records), msg="log_exceptions did not log exception")
+