diff --git a/pyobs/robotic/lco/taskschedule.py b/pyobs/robotic/lco/taskschedule.py index 6f8f9f59..1993b2f5 100644 --- a/pyobs/robotic/lco/taskschedule.py +++ b/pyobs/robotic/lco/taskschedule.py @@ -14,6 +14,7 @@ from .portal import Portal from .task import LcoTask from ...utils.logger import DuplicateFilter +from ...utils.logging.resolvableerror import ResolvableErrorLogger from ...utils.parallel import acquire_lock log = logging.getLogger(__name__) @@ -75,6 +76,9 @@ def __init__( # task list self._tasks: Dict[str, LcoTask] = {} + # error logging for regular updates + self._update_error_log = ResolvableErrorLogger(log, error_level=logging.WARNING) + async def open(self) -> None: """Open scheduler.""" await TaskSchedule.open(self) @@ -84,7 +88,7 @@ async def open(self) -> None: await self.update_now() # start update thread - asyncio.create_task(self._update_schedule()) + asyncio.ensure_future(asyncio.create_task(self._update_schedule())) async def _init_from_portal(self) -> None: """Initialize scheduler from portal.""" @@ -159,12 +163,13 @@ async def update_now(self, force: bool = False) -> None: # need update! try: tasks = await self._get_schedule(end_after=now, start_before=now + TimeDelta(24 * u.hour)) + self._update_error_log.resolve("Successfully updated schedule.") except TimeoutError: - log.error("Request timed out") + self._update_error_log.error("Request for updating schedule timed out.") await asyncio.sleep(60) return except RuntimeError: - log.warning("Could not fetch schedule.") + self._update_error_log.error("Could not fetch schedule.") return # any changes? diff --git a/pyobs/utils/logging/__init__.py b/pyobs/utils/logging/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/pyobs/utils/logging/resolvableerror.py b/pyobs/utils/logging/resolvableerror.py new file mode 100644 index 00000000..9cb8ab35 --- /dev/null +++ b/pyobs/utils/logging/resolvableerror.py @@ -0,0 +1,51 @@ +import logging +import time + + +class ResolvableErrorLogger: + def __init__( + self, + logger: logging.Logger, + error_level: int = logging.ERROR, + resolved_level: int = logging.INFO, + min_interval: int = 600, + ): + """Logging for resolvable errors. + + Args: + logger: Logger to use. + error_level: Log level for error. + resolved_level: Log level for resolved message. + min_interval: Minimum interval between error logs in seconds. + """ + self._log = logger + self._error_level = error_level + self._resolved_level = resolved_level + self._min_interval = min_interval + self._time_of_last_error = 0 + self._last_error_message = "" + + def error(self, msg: str, *args, **kwargs) -> None: + """Log an error message.""" + + # we log, if last message is old enough or text changed + if self._time_of_last_error - time.time() > self._min_interval or msg != self._last_error_message: + self._log.log(self._error_level, msg, *args, **kwargs) + + # store it + self._time_of_last_error = time.time() + self._last_error_message = msg + + def resolve(self, msg: str, *args, **kwargs): + """Resolve an error.""" + + # only log, if we had an actual error + if self._time_of_last_error > 0: + self._log.log(self._resolved_level, msg, *args, **kwargs) + + # reset + self._time_of_last_error = 0 + self._last_error_message = "" + + +__all__ = ["ResolvableErrorLogger"] diff --git a/pyproject.toml b/pyproject.toml index b7f4026e..473057cd 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,7 +1,7 @@ [tool.poetry] name = "pyobs-core" packages = [{ include = "pyobs" }] -version = "1.16.3" +version = "1.16.4" description = "robotic telescope software" authors = ["Tim-Oliver Husser "] license = "MIT" diff --git a/tests/utils/logging/__init__.py b/tests/utils/logging/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/tests/utils/logging/test_resolvableerror.py b/tests/utils/logging/test_resolvableerror.py new file mode 100644 index 00000000..701c4022 --- /dev/null +++ b/tests/utils/logging/test_resolvableerror.py @@ -0,0 +1,54 @@ +import logging + +from pyobs.utils.logging.resolvableerror import ResolvableErrorLogger + + +def create_logger(): + # create logger + logger = logging.getLogger("test_logger") + logger.setLevel(logging.DEBUG) + + # create console handler and set level to debug + ch = logging.StreamHandler() + ch.setLevel(logging.DEBUG) + + # create formatter + formatter = logging.Formatter("%(levelname)s - %(message)s") + + # add formatter to ch + ch.setFormatter(formatter) + + # add ch to logger + logger.addHandler(ch) + return logger + + +def test_logger(capsys): + # init + logger = create_logger() + rel = ResolvableErrorLogger(logger) + + # logging resolve should do nothing + rel.resolve("Resolve") + _, err = capsys.readouterr() + assert err == "" + + # logging error gives the error message + rel.error("Some error") + _, err = capsys.readouterr() + assert "ERROR - Some error" in err + + # Same should give nothing + rel.error("Some error") + _, err = capsys.readouterr() + assert err == "" + + # logging new error gives the error message + rel.error("Some new error") + _, err = capsys.readouterr() + assert "ERROR - Some new error" in err + + # logging resolve should output + rel.resolve("Resolved") + _, err = capsys.readouterr() + assert "INFO - Resolved" in err