diff --git a/esphome/util.py b/esphome/util.py index 136d6362f2..5bb341b700 100644 --- a/esphome/util.py +++ b/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. diff --git a/tests/unit_tests/test_util.py b/tests/unit_tests/test_util.py index 02309fbff8..bd3d3d4836 100644 --- a/tests/unit_tests/test_util.py +++ b/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