Add test / docs for more cmd log splitting possibilities

src/Shrun/Configuration/Data/CommandLogging/ReadSize.hs

@@ -92,6 +92,22 @@ instance Default ReadSize where
   --
   -- For now we choose option 2, increase the read-size as it is simple and
   -- appears to work well. We may choose to increase this in the future.
+  --
+  -- UPDATE: There is another way logs can be split. In some cases, a command
+  -- may output a "partial" line, with the expectation to be completed later.
+  -- For instance, our test framework outputs lines like:
+  --
+  --    Some test desc:               OK (0.05s)
+  --
+  -- But the line is outputted in two steps. First, the text description is
+  -- printed. Second, the OK (0.05s) happens _after_ the test completes.
+  -- If the time elapsed is long enough to outstrip the poll-interval, then
+  -- this log will be broken. Increasing the poll-interval is an option, but
+  -- that has other problems. And increasing the read-size will not help here.
+  --
+  -- The only real solution to this is to implement the more complicated
+  -- "read line" scheme described above. Of course this comes with its own
+  -- complications and trade-offs.
   def = MkReadSize $ MkBytes 16_000
 
 instance DecodeTOML ReadSize where

test/functional/Functional/Miscellaneous.hs

@@ -11,7 +11,8 @@ specs =
     [ splitNewlineLogs,
       spaceErrorLogs,
       stripControlAlwaysCmdNames,
-      reportsStderr
+      reportsStderr,
+      slowOutputBroken
     ]
 
 splitNewlineLogs :: TestTree
@@ -122,3 +123,40 @@ reportsStderr = testCase "Reports stderr" $ do
         withErrorPrefix scriptPath <> "1 second: some output",
         withErrorPrefix scriptPath <> "1 second: more output"
       ]
+
+-- This is an "anti" test. We actually do not want this behavior. Ideally,
+-- the lines:
+--
+--   echo -n "first: "
+--   sleep 1
+--   echo "second"
+--
+-- Should produce "first: second", since that is the original intention
+-- (-n means do not append a newline). But because the time between logs is
+-- longer than the poll-interval, it is split.
+--
+-- We include this test for documenting the current behavior, and if we ever
+-- "fix" this -- see NOTE: [Command log splitting] --, then we can simply
+-- flip the expected/unexpected below.
+slowOutputBroken :: TestTree
+slowOutputBroken = testCase "Slow output is broken" $ do
+  results <- run args
+  V.verifyExpectedUnexpected results expected unexpected
+  where
+    scriptPath :: (IsString a) => a
+    scriptPath = "./test/functional/Functional/slow_output_broken.sh"
+
+    args =
+      withNoConfig
+        [ "--console-log-command",
+          scriptPath
+        ]
+
+    expected =
+      [ withCommandPrefix scriptPath "first: ",
+        withCommandPrefix scriptPath "second"
+      ]
+
+    unexpected =
+      [ withCommandPrefix scriptPath "first: second"
+      ]

test/functional/Functional/slow_output_broken.sh

@@ -0,0 +1,4 @@
+echo -n "first: "
+sleep 1
+echo "second"
+sleep 0.5