[Haskell-cafe] Logging pure code

[Marco Túlio Gontijo e Silva]

Hi.

I'm using the hslogger library for logging pure code, using the
following function:

uLog :: Priority -> String -> a -> a
uLog pri str x = unsafePerformIO $ logM rootLoggerName pri str >> return x

Everything was working fine, till I used uLog on a very accessed
function.  Then the program started to fail with:

thread blocked indefinitely in an MVar operation

I've changed uLog to:

uLog :: Priority -> String -> a -> a
uLog pri str x = unsafePerformIO $ hPutStrLn stderr (show str) >> return x

And I noticed on the log that two messages were sent "at the same
time" on the point where the version with hslogger fails:

"canonicate 4 "canonicate 1 \r\n\t\t\t\t\t\t\t\tRio Branco = rio branco"
"canonicate 2 AC\r\n\t\t\t\t\t\t\t\t = ac"
ac = ac"

They were sent as (in any order):

"canonicate 4 ac = ac"
"canonicate 1 \r\n\t\t\t\t\t\t\t\tRio Branco = rio branco"
"canonicate 2 AC\r\n\t\t\t\t\t\t\t\t = ac"

I tried changing hslogger to avoid calling modifyMVar when getting
logger for rootLoggerName, and using withMVar instead, but the problem
persisted.  I tried to create a simple test case to reproduce the
problem, but I couldn't, all test cases I created worked as expected.

As I was with no other ideas, I tried some things that make little
sense.  This happens with optimization or without it.  Following
http://hackage.haskell.org/trac/ghc/ticket/5859 I tried using
-fno-state-hack, but the problem persisted.  I tried adding NOINLINE
to uLog, without success.  I also tried changing unsafePerformIO to
unsafeDupablePerformIO.

I thought that the only thing I needed to take care while using
unsafePerformIO was knowing that the time of execution is undetermined
and that it could even run more than once.  This is not a problem for
my logging.  Is there something else I should be aware while using
unsafePerformIO?

Greetings.

-- 
marcot
http://marcot.eti.br/