[core] Flush stdout in safe_print so logs stream live (#18261)

esphome/util.py

@@ -87,8 +87,11 @@ def safe_print(message="", end="\n"):
         except UnicodeEncodeError:
             pass
 
+    # Always flush: stdout is block buffered when it is a pipe (the dashboard
+    # runs us that way), so live log lines would otherwise sit in the buffer
+    # for a long time instead of streaming out.
     try:
-        print(message, end=end)
+        print(message, end=end, flush=True)
         return
     except UnicodeEncodeError:
         pass
@@ -104,6 +107,7 @@ def safe_print(message="", end="\n"):
         print(
             message.encode(encoding, "backslashreplace").decode(encoding),
             end=end,
+            flush=True,
         )
         return
     except UnicodeEncodeError:
@@ -113,9 +117,10 @@ def safe_print(message="", end="\n"):
         print(
             message.encode("ascii", "backslashreplace").decode("ascii"),
             end=end,
+            flush=True,
         )
     except UnicodeEncodeError:
-        print("Cannot print line because of invalid locale!")
+        print("Cannot print line because of invalid locale!", flush=True)
 
 
 def safe_input(prompt=""):
@@ -211,6 +216,11 @@ class RedirectText:
         else:
             self._write_color_replace(s)
 
+        # Same reason as safe_print: the dashboard gives us a pipe, which is
+        # block buffered, so in-process esptool progress would not show up
+        # until the buffer filled.
+        self._out.flush()
+
         # write() returns the number of characters written
         # Let's print the number of characters of the original string in order to not confuse
         # any caller.

tests/unit_tests/test_util.py

@@ -422,6 +422,26 @@ def _make_redirect(
     return redirect, buf
 
 
+def test_redirect_text_flushes_so_piped_output_streams() -> None:
+    """Regression: in-process esptool progress must reach the pipe right away.
+
+    ``run_external_command`` runs esptool inside our own process, so its
+    progress output goes through ``RedirectText.write``. That used to be
+    flushed only because ``colorama.init()`` wrapped stdout in a stream that
+    flushed after every write.
+    """
+    buf = io.BytesIO()
+    piped_stream = io.TextIOWrapper(
+        buf, encoding="utf-8", newline="\n", line_buffering=False
+    )
+    redirect = util.RedirectText(piped_stream)
+
+    redirect.write("Writing at 0x00010000 (50%)\r")
+
+    # No explicit flush here on purpose: RedirectText has to do it.
+    assert buf.getvalue() == b"Writing at 0x00010000 (50%)\r"
+
+
 def test_redirect_text_callback_called_on_matching_line() -> None:
     """Test that a line callback is called and its output is written."""
     results: list[str] = []
@@ -745,6 +765,31 @@ class TestSafePrint:
         util.safe_print("\033[0;32mhi\033[0m")
         assert capsys.readouterr().out == "\\033[0;32mhi\\033[0m\n"
 
+    def test_flushes_so_piped_output_streams(
+        self, monkeypatch: pytest.MonkeyPatch
+    ) -> None:
+        """Regression: each line must reach the OS pipe right away.
+
+        The dashboard runs ``esphome logs`` with stdout as a pipe, which
+        Python block buffers at 8 KiB. Log lines used to be flushed only
+        because ``colorama.init()`` wrapped stdout in a stream that flushed
+        after every write; once that wrapping was skipped for dashboard runs
+        the lines sat in the buffer and the log view stayed empty until
+        enough output piled up to fill it.
+        """
+        buf = io.BytesIO()
+        # newline="\n" keeps Windows from rewriting the terminator to "\r\n";
+        # this test is about flushing, not about line endings.
+        piped_stream = io.TextIOWrapper(
+            buf, encoding="utf-8", newline="\n", line_buffering=False
+        )
+        monkeypatch.setattr(sys, "stdout", piped_stream)
+
+        util.safe_print("live log line")
+
+        # No explicit flush here on purpose: safe_print has to do it.
+        assert buf.getvalue() == b"live log line\n"
+
     def test_fallback_writes_string_not_bytes_repr(
         self, monkeypatch: pytest.MonkeyPatch
     ) -> None:
@@ -764,7 +809,7 @@ class TestSafePrint:
         monkeypatch.setattr(sys, "stdout", cp1252_stream)
 
         util.safe_print("bars: \u2582\u2584\u2586\u2588 done")
-        cp1252_stream.flush()
+        # No explicit flush: the fallback path has to flush too.
         output = buf.getvalue().decode("cp1252")
 
         # Output is a clean line, not the bytes repr.
@@ -789,7 +834,7 @@ class TestSafePrint:
         monkeypatch.setattr(sys, "stdout", cp1252_stream)
 
         util.safe_print("\033[0;32m\u2582\u2584\u2586\u2588\033[0m")
-        cp1252_stream.flush()
+        # No explicit flush: the fallback path has to flush too.
         output = buf.getvalue().decode("cp1252")
 
         # Dashboard escaping turned ESC into literal "\033" (5 chars), which