Print statements not being executed in real time

Question

I have a wrapper around readCreateProcessWithExitCode that does an early exit whenever a non-zero exit code is returned, and returns the stdout output

import System.Process

runShell :: String -> String -> IO String
runShell cmd msg = do
  (ec, r, err) <- readCreateProcessWithExitCode (shell cmd) ""
  when (isFailure ec) (error $ msg <> ": " <> err)
  return r

From the docs page, readCreateProcessWithExitCode seems to be similar to the simpler readProcess, which claims to block until the forked process terminates.

Now the issue arises whenever I try to interleave logs to stdout myself using putStrLn.

fn :: IO ()
fn = do
  void $ runShell "lightweight" "err1"
  print "log1"
  void $ runShell "expensive" "err2"
  print "log2"

Assuming both commands executions are successful, and that the second one takes a few second to execute, the function should log "log1" almost immediately after running lightweight, wait a few seconds and then print "log2". That's not the case however - it appears that logs are being 'suspended' and only printed at the end of program execution, all at once.

I thought lazy evaluation had something to do with it, but explicitly evaluating the results of putStrLn didn't help either

() <- putStrLn "log1"

Answer 1

As Willem Van Onsem pointed out in a comment, there's some buffering going on with stdout by default. It can be disabled using

hSetBuffering stdout NoBuffering