logger
logger copied to clipboard
kazu-yamamoto
Flushing a single stdout logger doesn't seem to flush stdout
Apologies if I'm doing something wrong, but I would expect the following program,
module Main where
import Data.String
import System.Log.FastLogger
main :: IO ()
main = do
ls <- newStdoutLoggerSetN defaultBufSize $ Just 1
pushLogStrLn ls $ fromString "A log message"
flushLogStr ls
putStrLn "post-flush"
To output
A log message
post-flush
But instead it outputs,
post-flush
A log message
Tested with lts-22.18 / fast-logger-3.2.2
After some experimentation, it seems that when flushLogStr is called there is nothing yet to flush, as if pushLogStrLn is non-blocking and hasn't actually put anything in buffer when it completes. Adding the tiniest of delay (threadDelay 1) between push and flush makes it work correctly.
For context, I have a CLI application that logs and prompts the user. I am very careful to flush the logger before outputting the prompt, but the prompt shows up before the logging output. I've also seen cases where the CLI drops log messages when exiting due to an error (despite a manual flush with finally), which I suspect is related to this, but I can't prove it.
Let's close.
Sorry, there might be some confusion. I was saying the bug does not repro in 3.2.1, so it was introduced (and still exists) in 3.2.2.
My bad.
The difference of 3.2.1 and 3.2.2 is only 3f0adc0. The other commits are style only.
Could you try to revert 3f0adc0 to see if the bug is gone?
OK, I take back what I said. It seems with either 3.2.2 or 3.2.1 it reproduces, just intermittently. The bug was not introduced with 3.2.2.
I wrapped my repro in a script that runs it 20 times and only passes if it does the right thing all 20 times. I then ran that on each commit going back from the tip of main. I identified that this bug was introduced in https://github.com/kazu-yamamoto/logger/commit/e1454934579135a086c6242a8018b713f14fba74.
9 changed files with 393 additions and 162 deletions.
:scream:
OK. I understand the source of this problem.
A dedicated thread is spawn if N is 1.
So, this is the contention for stdout among two threads.
flushLogStr should wait for the dedicated thread somehow.