Fix for delaying logging with timeouts.

pekkaklarck · pekkaklarck · commit afeb10578239 · 2025-04-30T12:50:55.000+03:00
Previous messages weren't restored meaning that messages could be lost. The unused variable also made linters unhappy. This code attemps to avoid problems with timeouts interrupting writing to output files. The current code was written to fix #5395 and is basically a rewrite of the fix for #2839. As #5417 explains, there are still problems and bigger changes are needed.
diff --git a/atest/robot/standard_libraries/builtin/used_in_custom_libs_and_listeners.robot b/atest/robot/standard_libraries/builtin/used_in_custom_libs_and_listeners.robot
@@ -29,6 +29,9 @@ Use BuiltIn keywords with timeouts
     Check Log Message    ${tc[3, 0, 1]}    42
     Check Log Message    ${tc[3, 1, 0]}    Test timeout 1 day active. * seconds left.    level=DEBUG    pattern=True
     Check Log Message    ${tc[3, 1, 1]}    \xff
+    # This message is in wrong place due to it being delayed and child keywords being logged first.
+    # It should be in position [3, 0], not [3, 2].
+    Check Log Message    ${tc[3, 2]}       Test timeout 1 day active. * seconds left.    level=DEBUG    pattern=True
 
 User keyword used via 'Run Keyword'
     ${tc} =    Check Test Case    ${TESTNAME}
diff --git a/src/robot/output/outputfile.py b/src/robot/output/outputfile.py
@@ -53,13 +53,13 @@ def _get_logger(self, path, rpa, legacy_output):
     @property
     @contextmanager
     def delayed_logging(self):
-        self._delayed_messages, prev_messages = [], self._delayed_messages
+        self._delayed_messages, previous = [], self._delayed_messages
         try:
             yield
         finally:
-            self._delayed_messages, messages = None, self._delayed_messages
-            for msg in messages or ():
-                self.log_message(msg)
+            self._delayed_messages, messages = previous, self._delayed_messages
+            for msg in messages:
+                self.log_message(msg, no_delay=True)
 
     def start_suite(self, data, result):
         self.logger.start_suite(result)
@@ -170,14 +170,15 @@ def start_error(self, data, result):
     def end_error(self, data, result):
         self.logger.end_error(result)
 
-    def log_message(self, message):
+    def log_message(self, message, no_delay=False):
         if self.is_logged(message):
-            if self._delayed_messages is None:
+            if self._delayed_messages is None or no_delay:
                 # Use the real logger also when flattening.
                 self.real_logger.message(message)
             else:
-                # Logging is delayed when using timeouts to avoid timeouts
-                # killing output writing that could corrupt the output.
+                # Logging is delayed when using timeouts to avoid writing to output
+                # files being interrupted. There are still problems, though:
+                # https://github.com/robotframework/robotframework/issues/5417
                 self._delayed_messages.append(message)
 
     def message(self, message):
