SW-3537 laserhead none will crash plugin

octoprint_mrbeam/iobeam/laserhead_handler.py

@@ -92,7 +92,7 @@ def _current_used_lh_model_string(self):
         try:
             return laser_head_model_str_list.pop(0)
         except IndexError:
-            self._logger.error("Unknown laserhead model,  name: {} ID: {}".format(
+            self._logger.error("Unknown laserhead model, name: {} ID: {}".format(
                 self._current_used_lh_model, self._current_used_lh_model_id))
             return str(None)
 

octoprint_mrbeam/mrb_logger.py

@@ -34,6 +34,8 @@ def __init__(self, id, ignorePrinter=False, lvl=None):
         self.id = id
         self.id_short = self._shorten_id(id)
         self.my_buffer = []
+        self.messages_to_log = []  # list of messages to log, to prevent recursive logs
+        self.recursive_depth = 0
         # TODO: this line overrides logging.yaml!!!
         if lvl is not None:
             self.logger.setLevel(lvl)
@@ -84,6 +86,17 @@ def log(self, level, msg, *args, **kwargs):
         :param terminal_dump: Collect and log a terminal dump. Terminal dumps are also sent to analytics if analytics is not explicitly set to False.
         :type kwargs:
         """
+        if "Recursive call for log: %s" % msg in self.messages_to_log:
+            # we already logged this message, don't log it again
+            return
+
+        if msg in self.messages_to_log:
+            # change the log message that this is a recursive call
+            level = logging.ERROR
+            msg = "Recursive call for log: %s" % (msg)
+            kwargs["analytics"] = True
+
+        self.messages_to_log.append(msg)  # to prevent recursive calls
 
         try:
             if isinstance(msg, unicode):
@@ -96,7 +109,10 @@ def log(self, level, msg, *args, **kwargs):
             # If it's already unicode we get this TypeError
             pass
         except Exception as exc:
-            self.log(logging.ERROR, "Error in MrbLogger.log: %s - %s", msg, exc)
+            # self.log(logging.ERROR, "Error in MrbLogger.log: %s - %s", msg, exc)
+            level = logging.ERROR
+            msg = "Error in MrbLogger.log: %s - %s", msg, exc
+            kwargs["analytics"] = True
         if kwargs.pop("terminal", True if level >= logging.WARN else False):
             self._terminal(level, msg, *args, **kwargs)
         if kwargs.pop("terminal_as_comm", False) or level == self.LEVEL_COMM:
@@ -130,6 +146,10 @@ def log(self, level, msg, *args, **kwargs):
         except IOError:
             print(">>", msg)
 
+        # remove the message from the list
+        index_to_remove = self.messages_to_log.index(msg)
+        self.messages_to_log.pop(index_to_remove)
+
     def _terminal(self, level, msg, *args, **kwargs):
         global _printer
 

tests/analytics/test_analytics_handler.py

@@ -44,7 +44,7 @@ def test_add_high_temp_warning_state_transition(mrbeam_plugin):
     )
 
 
-def test_on_event_high_temperature_dismissed(analytics_handler, mrbeam_plugin):
+def test_on_event_high_temperature_dismissed(analytics_handler):
     # Arrange
     analytics_handler._add_device_event = MagicMock()
 
@@ -59,7 +59,7 @@ def test_on_event_high_temperature_dismissed(analytics_handler, mrbeam_plugin):
     )
 
 
-def test_on_event_high_temperature_warning(analytics_handler, mrbeam_plugin):
+def test_on_event_high_temperature_warning(analytics_handler):
     # Arrange
     analytics_handler._add_device_event = MagicMock()
 
@@ -74,7 +74,7 @@ def test_on_event_high_temperature_warning(analytics_handler, mrbeam_plugin):
     )
 
 
-def test_on_event_laser_cooling_to_slow(analytics_handler, mrbeam_plugin):
+def test_on_event_laser_cooling_to_slow(analytics_handler):
     # Arrange
     analytics_handler._add_device_event = MagicMock()
 
@@ -89,7 +89,7 @@ def test_on_event_laser_cooling_to_slow(analytics_handler, mrbeam_plugin):
     )
 
 
-def test_on_event_laser_cooling_re_trigger_fan(analytics_handler, mrbeam_plugin):
+def test_on_event_laser_cooling_re_trigger_fan(analytics_handler):
     # Arrange
     analytics_handler._add_device_event = MagicMock()
 
@@ -121,7 +121,7 @@ def test_on_event_laser_high_temperature(analytics_handler, mrbeam_plugin):
     )
 
 
-def test_on_event_high_temperature_shown_critical(analytics_handler, mrbeam_plugin):
+def test_on_event_high_temperature_shown_critical(analytics_handler):
     # Arrange
     analytics_handler._add_device_event = MagicMock()
 
@@ -136,7 +136,7 @@ def test_on_event_high_temperature_shown_critical(analytics_handler, mrbeam_plug
     )
 
 
-def test_on_event_high_temperature_shown_warning(analytics_handler, mrbeam_plugin):
+def test_on_event_high_temperature_shown_warning(analytics_handler):
     # Arrange
     analytics_handler._add_device_event = MagicMock()
 

tests/test_mrb_logger.py

@@ -0,0 +1,54 @@
+import __builtin__
+import logging
+
+import pytest
+from mock.mock import MagicMock, call
+
+from octoprint_mrbeam.mrb_logger import MrbLogger
+
+
+@pytest.fixture
+def mrb_logger():
+    logger = MrbLogger("mock_logger")
+    logger._get_analytics_handler = MagicMock()
+    __builtin__._mrbeam_plugin_implementation = MagicMock()
+    logger._terminal = MagicMock()
+    return logger
+
+
+def test_error_log(mrb_logger):
+    # Arrange
+    mrb_logger.log = MagicMock()
+
+    # Act
+    mrb_logger.error("test")
+
+    # Assert
+    mrb_logger.log.assert_called_once_with(logging.ERROR, "test", analytics=True)
+
+
+def test_recursive_log(mrb_logger):
+    # Arrange
+    mrb_logger.logger.log = MagicMock()
+
+    def analytics_log_event_side_effect(*args, **kwargs):
+        print("log - {} - {}".format(args[0], args[1]))
+        # trigger a log during the log
+        mrb_logger.error("recursive log")
+
+    mrb_logger._analytics_log_event = MagicMock(
+        side_effect=analytics_log_event_side_effect
+    )
+
+    # Act
+    # log an error
+    mrb_logger.error("test")
+
+    # Assert
+    mrb_logger.logger.log.assert_has_calls(
+        [
+            call(logging.ERROR, "Recursive call for log: recursive log"),
+            call(logging.ERROR, "recursive log"),
+            call(logging.ERROR, "test"),
+        ]
+    )