Read log output by chunks if a line is too long

Fixes #1096.

Signed-off-by: Yusuke Matsubara <whym@whym.org>

newsfragments/long-log-lines.bugfix

@@ -0,0 +1 @@
+Fix freeze caused by too long log lines without a newline.

podman_compose.py

@@ -10,6 +10,7 @@
 from __future__ import annotations
 
 import argparse
+import asyncio.exceptions
 import asyncio.subprocess
 import getpass
 import glob
@@ -1426,6 +1427,47 @@ async def output(self, podman_args, cmd="", cmd_args=None):
 
             raise subprocess.CalledProcessError(p.returncode, " ".join(cmd_ls), stderr_data)
 
+    async def _readchunk(self, reader):
+        try:
+            return await reader.readuntil(b"\n")
+        except asyncio.exceptions.IncompleteReadError as e:
+            return e.partial
+        except asyncio.exceptions.LimitOverrunError as e:
+            return await reader.read(e.consumed)
+
+    async def _format_stream(self, reader, sink, log_formatter):
+        line_ongoing = False
+
+        def _formatted_print_with_nl(s):
+            if line_ongoing:
+                print(s, file=sink, end="\n")
+            else:
+                print(log_formatter, s, file=sink, end="\n")
+
+        def _formatted_print_without_nl(s):
+            if line_ongoing:
+                print(s, file=sink, end="")
+            else:
+                print(log_formatter, s, file=sink, end="")
+
+        while not reader.at_eof():
+            chunk = await self._readchunk(reader)
+            parts = chunk.split(b"\n")
+
+            # Iff parts ends with '', the last part is a incomplete line;
+            # The rest are complete lines
+
+            for i, part in enumerate(parts):
+                if i < len(parts) - 1:
+                    _formatted_print_with_nl(part.decode())
+                    line_ongoing = False
+                elif len(part) > 0:
+                    _formatted_print_without_nl(part.decode())
+                    line_ongoing = True
+        else:
+            if line_ongoing:
+                print(file=sink, end="\n")  # End the unfinished line
+
     def exec(
         self,
         podman_args,
@@ -1457,26 +1499,21 @@ async def run(  # pylint: disable=dangerous-default-value
                 return None
 
             if log_formatter is not None:
-
-                async def format_out(stdout):
-                    while True:
-                        line = await stdout.readline()
-                        if line:
-                            print(log_formatter, line.decode('utf-8'), end='')
-                        if stdout.at_eof():
-                            break
-
                 p = await asyncio.create_subprocess_exec(
                     *cmd_ls, stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.PIPE
                 )  # pylint: disable=consider-using-with
 
                 # This is hacky to make the tasks not get garbage collected
                 # https://github.com/python/cpython/issues/91887
-                out_t = asyncio.create_task(format_out(p.stdout))
+                out_t = asyncio.create_task(
+                    self._format_stream(p.stdout, sys.stdout, log_formatter)
+                )
                 task_reference.add(out_t)
                 out_t.add_done_callback(task_reference.discard)
 
-                err_t = asyncio.create_task(format_out(p.stderr))
+                err_t = asyncio.create_task(
+                    self._format_stream(p.stderr, sys.stdout, log_formatter)
+                )
                 task_reference.add(err_t)
                 err_t.add_done_callback(task_reference.discard)
 

tests/unit/test_compose_run_log_format.py

@@ -0,0 +1,58 @@
+# SPDX-License-Identifier: GPL-2.0
+# pylint: disable=protected-access
+
+import io
+import unittest
+
+from podman_compose import Podman
+
+
+class DummyReader:
+    def __init__(self, data=[]):
+        self.data = data
+
+    async def readuntil(self, x):
+        return self.data.pop(0)
+
+    def at_eof(self):
+        return len(self.data) == 0
+
+
+class TestComposeRunLogFormat(unittest.IsolatedAsyncioTestCase):
+    def setUp(self):
+        self.p = get_minimal_podman()
+        self.buffer = io.StringIO()
+
+    async def test_single_line_single_chunk(self):
+        reader = DummyReader([b'hello, world\n'])
+        await self.p._format_stream(reader, self.buffer, 'LL:')
+        self.assertEqual(self.buffer.getvalue(), 'LL: hello, world\n')
+
+    async def test_empty_line(self):
+        reader = DummyReader([b'\n'])
+        await self.p._format_stream(reader, self.buffer, 'LL:')
+        self.assertEqual(self.buffer.getvalue(), 'LL: \n')
+
+    async def test_line_split(self):
+        reader = DummyReader([b'hello,', b' world\n'])
+        await self.p._format_stream(reader, self.buffer, 'LL:')
+        self.assertEqual(self.buffer.getvalue(), 'LL: hello, world\n')
+
+    async def test_two_lines_in_one_chunk(self):
+        reader = DummyReader([b'hello\nbye\n'])
+        await self.p._format_stream(reader, self.buffer, 'LL:')
+        self.assertEqual(self.buffer.getvalue(), 'LL: hello\nLL: bye\n')
+
+    async def test_double_blank(self):
+        reader = DummyReader([b'hello\n\n\nbye\n'])
+        await self.p._format_stream(reader, self.buffer, 'LL:')
+        self.assertEqual(self.buffer.getvalue(), 'LL: hello\nLL: \nLL: \nLL: bye\n')
+
+    async def test_no_new_line_at_end(self):
+        reader = DummyReader([b'hello\nbye'])
+        await self.p._format_stream(reader, self.buffer, 'LL:')
+        self.assertEqual(self.buffer.getvalue(), 'LL: hello\nLL: bye\n')
+
+
+def get_minimal_podman():
+    return Podman(None)