Repository: jamesoff/simplemonitor

Issue:
mqtt logger (maybe all?) report failure even when monitors are not run
I've got a simple two monitor config; one a ping check that runs every 30 seconds, and one a speedtest that runs every 15 minutes (via `gap` on the monitor).  My verbose app output looks like this:

```
2020-11-19 22:59:10     INFO (simplemonitor) monitor passed: google-ping
2020-11-19 22:59:12     INFO (simplemonitor) monitor passed: wancheck
2020-11-19 22:59:46  WARNING (simplemonitor) monitor failed but within tolerance: google-ping
2020-11-19 22:59:46     INFO (simplemonitor) Not run: wancheck
2020-11-19 23:00:16     INFO (simplemonitor) monitor passed: google-ping
2020-11-19 23:00:16     INFO (simplemonitor) Not run: wancheck
```

etc.

If I configure a mqtt logger connected to Home Assistant, for the monitors that are not run, an "off" state is reported:

<img width="390" alt="Screen Shot 2020-11-19 at 3 04 13 PM" src="https://user-images.githubusercontent.com/194965/99734912-82924c00-2a78-11eb-94fd-c7a9390e2a74.png">

I have `only_failures=0` on the `mqtt` reporter as I'd like to have a heartbeat of the successes.  I think if a monitor is not run due to gap, no state should be logged?

Discussion:

Patch:
diff --git a/.python-version b/.python-version
index a08ffae..f870be2 100644
--- a/.python-version
+++ b/.python-version
@@ -1,1 +1,1 @@
-3.8.2
+3.10.1
diff --git a/docs/loggers.rst b/docs/loggers.rst
index ff38683..5590c72 100644
--- a/docs/loggers.rst
+++ b/docs/loggers.rst
@@ -56,6 +56,14 @@ These options are common to all logger types.
     * ``timestamp`` (UNIX timestamp)
     * ``iso8601`` (``YYYY-MM-DDTHH:MM:SS``)
 
+.. confval:: heartbeat
+
+    :type: bool
+    :required: false
+    :default: ``false``
+
+    if set, the logger only logs for monitors which executed on an iteration. Intended to be combined with the :ref:`gap<gap>` property of a Monitor.
+
 .. _loggers-list:
 
 Loggers
diff --git a/old_docs/logging.md b/old_docs/logging.md
index 29594df..0dd9285 100644
--- a/old_docs/logging.md
+++ b/old_docs/logging.md
@@ -27,6 +27,7 @@ The section name should be the name of your logger. This is the name you should
 | depend | lists (comma-separated, no spaces) the names of the monitors this logger depends on. Use this if the database file lives over the network. If a monitor it depends on fails, no attempt will be made to update the database.| no | |
 | groups | comma-separated list of monitor groups this logger should operate for. Use `_all` to match all groups. | no | "default" |
 | tz | The [timezone](https://en.wikipedia.org/wiki/List_of_tz_database_time_zones) the logger should convert date/times to. | no | UTC |
+| heartbeat | If set, the logger only logs for monitors which executed on an iteration. Intended to be combined with the `gap` property of a Monitor. | no | 0 |
 
 ### <a name="db"></a><a name="dbstatus"></a>db and dbstatus loggers
 
diff --git a/simplemonitor/Loggers/logger.py b/simplemonitor/Loggers/logger.py
index 5273141..5418bbb 100644
--- a/simplemonitor/Loggers/logger.py
+++ b/simplemonitor/Loggers/logger.py
@@ -53,6 +53,10 @@ class Logger:
 
         if self._global_info is None:
             self._global_info = {}
+        self.heartbeat = cast(
+            bool,
+            self.get_config_option("heartbeat", required_type="bool", default=False),
+        )
 
     def __enter__(self) -> None:
         """Context manager entry."""
diff --git a/simplemonitor/Monitors/monitor.py b/simplemonitor/Monitors/monitor.py
index 408d47c..0ee8f37 100644
--- a/simplemonitor/Monitors/monitor.py
+++ b/simplemonitor/Monitors/monitor.py
@@ -107,6 +107,7 @@ class Monitor:
         self._force_run = True  # set to ensure we re-run ASAP after a HUP
         if self._first_load is None:
             self._first_load = arrow.utcnow()
+        self.ran_this_time = False
 
     def get_config_option(
         self,
diff --git a/simplemonitor/simplemonitor.py b/simplemonitor/simplemonitor.py
index dda5841..d11a9e7 100644
--- a/simplemonitor/simplemonitor.py
+++ b/simplemonitor/simplemonitor.py
@@ -402,6 +402,7 @@ class SimpleMonitor:
         """Clear all all monitors' dependency info back to default."""
         for key in list(self.monitors.keys()):
             self.monitors[key].reset_dependencies()
+            self.monitors[key].ran_this_time = False
 
     def _verify_dependencies(self) -> bool:
         """Check if all monitors have valid dependencies."""
@@ -460,6 +461,7 @@ class SimpleMonitor:
         try:
             if monitor.should_run():
                 did_run = True
+                monitor.ran_this_time = True
                 start_time = time.time()
                 monitor.run_test()
                 end_time = time.time()
@@ -585,9 +587,7 @@ class SimpleMonitor:
         logger.check_dependencies(self.failed + self.still_failing + self.skipped)
         with logger:
             for key, monitor in self.monitors.items():
-                if check_group_match(monitor.group, logger.groups):
-                    logger.save_result2(key, monitor)
-                else:
+                if not check_group_match(monitor.group, logger.groups):
                     module_logger.debug(
                         "not logging for %s due to group mismatch (monitor in group %s, "
                         "logger has groups %s",
@@ -595,6 +595,16 @@ class SimpleMonitor:
                         monitor.group,
                         logger.groups,
                     )
+                    continue
+                if logger.heartbeat and not monitor.ran_this_time:
+                    module_logger.debug(
+                        "not logging for %s as this logger is in heartbeat mode and"
+                        " the monitor did not run this loop",
+                        key,
+                    )
+                    continue
+                logger.save_result2(key, monitor)
+
             try:
                 # need to work on a copy here to prevent the dicts changing under us
                 # during the loop, as remote instances can connect and update our data


Test patch:
diff --git a/tests/test_logger.py b/tests/test_logger.py
index f52481f..74dbe59 100644
--- a/tests/test_logger.py
+++ b/tests/test_logger.py
@@ -107,6 +107,40 @@ class TestLogger(unittest.TestCase):
             s.log_result(this_logger)
         mock_method.assert_called_once()
 
+    def test_heartbeat_off(self):
+        with patch.object(logger.Logger, "save_result2") as mock_method:
+            this_logger = logger.Logger({})
+            s = SimpleMonitor(Path("tests/monitor-empty.ini"))
+            s.add_monitor("test", MonitorNull("unnamed"))
+            s.add_logger("test", this_logger)
+            s.run_loop()
+            s.run_loop()
+            self.assertEqual(mock_method.call_count, 2)
+
+    def test_heartbeat_on(self):
+        with patch.object(logger.Logger, "save_result2") as mock_method:
+            this_logger = logger.Logger({"heartbeat": 1})
+            this_monitor = MonitorNull("unnamed", {"gap": 10})
+            s = SimpleMonitor(Path("tests/monitor-empty.ini"))
+            s.add_monitor("test", this_monitor)
+            s.add_logger("test", this_logger)
+            s.run_loop()
+            s.run_loop()
+            mock_method.assert_called_once()
+
+    def test_reset_monitor(self):
+        s = SimpleMonitor(Path("tests/monitor-empty.ini"))
+        s.add_monitor("monitor1", MonitorNull("monitor1"))
+        s.add_monitor("monitor2", MonitorNull("monitor2", {"depend": "monitor1"}))
+        s.run_loop()
+        self.assertTrue(s.monitors["monitor1"].ran_this_time)
+        self.assertTrue(s.monitors["monitor2"].ran_this_time)
+        self.assertEqual(s.monitors["monitor2"].remaining_dependencies, [])
+        s.reset_monitors()
+        self.assertFalse(s.monitors["monitor1"].ran_this_time)
+        self.assertFalse(s.monitors["monitor2"].ran_this_time)
+        self.assertEqual(s.monitors["monitor2"].remaining_dependencies, ["monitor1"])
+
 
 class TestFileLogger(unittest.TestCase):
     @freeze_time("2020-04-18 12:00+00:00")