haskell-hvr / hslogger Goto Github PK

http://software.complete.org/software/issues/show/178

Added by Magnus Therning 2009-08-23. ALL TEXT BELOW FROM SUBMITTER.

On my Arch system I ran into the following problem:

> :m +System.Log.Logger
> :m +System.Log.Handler.Syslog
> sl <- openlog "foo" [PID] USER DEBUG
> updateGlobalLogger rootLoggerName (addHandler sl)
> warningM "bar" "test" 
*** Exception: sendTo: protocol error (Protocol wrong type for socket)

I also tried using a UDP socket (by modifying the syslog-ng config to include @unix-dgram("/dev/dlog")), but that doesn't seem to fix it:

> :m +System.Log.Logger
> :m +System.Log.Handler.Syslog
> sl <- openlog_local "/dev/dlog" "foo" [PID] USER DEBUG
> updateGlobalLogger rootLoggerName (addHandler sl)
> warningM "bar" "test" 
*** Exception: sendTo: protocol error (Protocol wrong type for socket)

I've tried the same on a Debian box. With sysklogd I don't have any problems, but after switching to syslog-ng I see exactly the same behaviour as on my Arch system.

The version on Arch is 1.0.7, and the version on Debian is 1.0.8. (Have you forgot to push the latest version to Hackage again? ;-)

http://article.gmane.org/gmane.comp.lang.haskell.cafe/62709

Please update upper version for network dependency to < 2.5.

cabal install hslogger fails with

Error: cabal: Failed to download hslogger-1.3.1.1 (which is required by
exe:haskell-debug-adapter from haskell-debug-adapter-0.0.39.0). The exception
was:
Unexpected response 503 for
http://objects-us-east-1.dream.io/hackage-mirror/package/hslogger-1.3.1.1.tar.gz

I am new to haskell and I installed cabal via ghcup using the official instructions on Ubuntu 22. I can install other packages fine so this does not seem like a Hackage outage.

I'm experiencing a really weird problem where a small Haskell program using hslogger will livelock and use all of the (8) CPUs on my laptop at 100%. I'm not totally sure that hslogger is to blame but it definitely seems to be part of the interaction that is happening, and I'd greatly appreciate any help.

The full repro can be found here: https://github.com/thomasjm/haskell-livelock-repro. You can simply clone this repo and run stack install && high-cpu-debug-exe.

Here's the code and the debugging I've attempted:

main :: IO ()
main = do
  -- Remove the default handler and set our own.
  -- If you use the default handler, the problem doesn't happen.
  updateGlobalLogger rootLoggerName removeHandler
  handler <- streamHandler stderr DEBUG
  -- If the message is just "$msg" instead of "Msg: $msg", the problem doesn't happen
  updateGlobalLogger rootLoggerName (addHandler $ setFormatter handler $ simpleLogFormatter "Msg: $msg")
  let logFn = warningM "MyApp"

  -- Repeat this 20 times
  replicateM_ 20 $ do
    logFn [i|Spawning spawnWithPty|]
    forkIO $ do
      logFn [i|Doing spawnWithPty|]
      void $ spawnWithPty Nothing True "sleep" ["99999999"] (80, 24)

    logFn [i|Spawning readCreateProcess|]
    forkIO $ void $ do
      logFn [i|Doing readCreateProcess|]
      liftIO $ readCreateProcess (proc "echo" ["hi"]) ""

  -- All CPUs should now be stuck at 100%
  threadDelay 60000000

This program sets up a simple log handler that prints to stderr. Then it runs a loop where it forks threads that do either spawnWithPty (to create a new process inside a pseuo-terminal) or readCreateProcess (to create a normal process). I know this is weird, but if you remove either of these then it doesn't trigger the problem.

• I've tried profiling with +RTS -p h but the profiling report doesn't show anything about the massive amount of CPU time being wasted (!)
• I've tried compiling with DWARF symbols and using perf to record the top symbols. 90% of the time is being spent in gcWorkerThread but I'm not sure what to make of that fact.
• I've tried compiling with -debug and running with +RTS -v to see the runtime logging, but I haven't gotten any insight from that.
• I know that spawnWithPty does FFI to create new pseudo-terminals, and my current theory is that some kind of multithreading/FFI race condition is happening.

https://github.com/jgoerzen/hslogger/blob/9368275658d465e0738247dfeec4233021c877b4/src/System/Log/Logger.hs#L479

I get the following error when compiling:

src/System/Log/Logger.hs:479:27: error:
    • Data.Map.fold is gone. Use foldr.
    • In the expression:
        Map.fold (\ l r -> concat [r, handlers l]) [] lt
      In an equation for ‘allHandlers’:
          allHandlers = Map.fold (\ l r -> concat [r, handlers l]) [] lt
      In the expression:
        do let allHandlers = Map.fold (\ l r -> ...) ... lt
           mapM_ (\ (HandlerT h) -> close h) allHandlers
           return $ Map.map (\ l -> l {handlers = []}) lt
    |
479 |         let allHandlers = Map.fold (\l r -> concat [r, handlers l]) [] lt
    |                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Failed to install hslogger-1.2.10

The fix seems to be trivial: just replacing fold with foldr as the error message advices, but I'm not sure about backward compatibility.

I often have occasion to allow the user to specify a Priority on the command line or in a configuration file. The libraries for such things demand Data and Typeable instances, and while an orphan instance is fine, I think it's harmless and simpler to move them into the library.

Would it be possible to add hslogger to Stackage? We'd like to add ghcide to Stackage, which relies on hslogger, and having it already there would make that much simpler.

In order notably to return logging information if a client requests it

Error occurs when attempting to log anything in SDL application

: hPutChar: invalid argument (Bad file descriptor)

I made test application in EPashkin/hslogger_SDL_test bad branch
Problem can be fixed on application side if call removeAllHandlers before any log action (ex. in start setupLogger).
Source of problem is very strange value of stderr. Don't found way detect it, stderr still opened and writable. Simply hPutChar stderr 'g' will also fail.

P.S. Failing handler IMHO created in System.Log.Logger.logTree.
P.P.S. When application started from console (cabal run) it works fine even on WARNING,
but hPutChar stderr 'g' still failing. (Sorry, was wrong. Error still showing.)

It's probably not wise to use the URL [email protected]:jgoerzen/hslogger.git in the Cabal file as that location requires SSH access to github to access the repository.

With -Wall I get:

src/System/Log/Handler/Syslog.hs:266:19: warning: [-Wincomplete-patterns]
    Pattern match(es) are non-exhaustive
    In a case alternative:
        Patterns not matched:
            network-3.1.2.5:Network.Socket.Types.SocketType
            (Foreign.C.Types.CInt (GHC.Int.I32# _))
    |
266 |           sent <- case sock_type sh of
    |                   ^^^^^^^^^^^^^^^^^^^^...

Compare https://hackage.haskell.org/package/network-3.1.2.5/docs/Network-Socket.html#t:SocketType.

If this lack of coverage is unproblematic, it would be nice if there was at least a comment that explains the issue,

Not quite true, it seems to use the message priority internally for filtering, but seems to use the handler's priority in the message that goes to syslog rather than the message's priority.

A couple of lines from a strace output:

5797  sendto(22, "<134>cluster[5797]: [cluster/INF"..., 56, 0, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 56
5800  sendto(22, "<134>cluster[5797]: [cluster/WAR"..., 105, 0, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 1

<134> is local0.info which is correct for the first line but wrong for the second as that was sent with WARNING priority.

My handler is created with

sysLog <- openlog "cluster" [PID] LOCAL0 INFO

If I change this to

sysLog <- openlog "cluster" [PID] LOCAL0 DEBUG

(but change nothing else) then the messages are logged at DEBUG priority (<135>):

6055  sendto(22, "<135>cluster[6055]: [cluster/INF"..., 56, 0, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 56
6056  sendto(22, "<135>cluster[6055]: [cluster/WAR"..., 105, 0, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 1

First noticed in 1.2.8 but still seems to be an issue in HEAD (c9433f8) despite that code now looking correct.

At least the base bounds need to be relaxed

hslogger seems to deadlock when printing lazy bytestrings.

I am guessing this is because hslogger has a global lock which won't be released until the lazy string is fully evaluated. This will lead to a deadlock if another thread whose actions determine the evaluation of the string also tries to log.

Test case: (sorry i couldn't make up a smaller one)

(server.hs)
import System.Log.Logger
import System.IO
import Control.Concurrent
import Network
import Control.DeepSeq
import Control.Exception

import qualified Data.ByteString.Lazy as L

main = do
updateGlobalLogger "Main" (setLevel NOTICE)
socket <- listenOn (PortNumber 11111)

putStrLn "(SERVER) Waiting for client to connect"
(hndle, _, _) <- accept socket
hSetBuffering hndle NoBuffering
putStrLn "(SERVER) Client connected"

forkIO (thread hndle)

--toPrint <- evaluate . force . show =<< L.hGetContents hndle
toPrint <- return . show =<< L.hGetContents hndle

noticeM "Main" ("Deadlock! :) " ++ toPrint)
return ()

thread hndle = do
noticeM "Main" $ "Never to be seen"
hPutStrLn hndle "Some Message"

(client.hs)
import System.IO
import Network

import qualified Data.ByteString.Char8 as L

main = do
putStrLn "(CLIENT) Connecting..."
hndle <- connectTo "localhost" (PortNumber 11111)
hSetBuffering hndle NoBuffering
putStrLn "(CLIENT) Connected"
toEcho <- hGetLine hndle
putStrLn $ "(CLIENT) Echoing " ++ show toEcho ++ " back to server"
hFlush stdout
hPutStr hndle toEcho
putStrLn "(CLIENT) Message sent"

Compile, then run server.hs then client.hs - it will deadlock. Commenting/Uncommenting the "toPrint <-..." lines in server.hs will solve the issue.

A simple solution is to force evaluating the string before acquiring the global lock.

Thanx for the update to hslogger supporting time >= 1.5 !

Unfortunately there seems to be a problem regarding the dependency limits in hslogger.cabal causing cabal to fail with the following error:

trying: hslogger-1.2.7:-buildtests
rejecting: hslogger-1.2.7:+small_base (conflict: Cabal =>
time==1.5.0.1/installed-13a..., hslogger-1.2.7:small_base => time<1.5)
rejecting: hslogger-1.2.7:-small_base (conflict:
base==4.8.0.0/installed-189..., hslogger-1.2.7:small_base => base<3)

I believe the limit on time < 1.5 in hslogger.cabal might be the culprit here.

In general the current Hackage release (1.2.6 in this case) ought to be available in the repository at any given time. It does not appear that this is currently the case.

Shouldn't logger ignore exceptions on output error by default? It seems to me that a frequent case of using e.g. errorM is in exception handlers; failing errorM will wreak havoc in many of these places. Wouldn't it be better if these calls ignored exceptions by default?

The logging functions appear to consistently throw the following when given logger names that start with a dot:

*** Exception: Maybe.fromJust: Nothing

For example:

errorM "." "foo"

We are on Linux. We just discovered that even though the socket is opened in datagram mode, writing to the /dev/log socket can still block if the queue is full, unless the socket is opened in nonblocking mode. This means that our application using hslogger will hang if syslog is broken. Alternatively, logging to localhost UDP 514 would also fix this problem.

Hslogger doesn't build with time 1.5:

[2 of 8] Compiling System.Log.Formatter ( src/System/Log/Formatter.hs, dist/dist-sandbox-1b7e0ad6/build/System/Log/Formatter.o )

src/System/Log/Formatter.hs:74:37:
    Couldn't match expected type ‘time-1.5:Data.Time.Format.Locale.TimeLocale’
                with actual type ‘System.Locale.TimeLocale’
    NB: ‘time-1.5:Data.Time.Format.Locale.TimeLocale’
          is defined in ‘Data.Time.Format.Locale’ in package ‘time-1.5’
        ‘System.Locale.TimeLocale’
          is defined in ‘System.Locale’ in package ‘old-locale-1.0.0.6’
    In the first argument of ‘formatTime’, namely ‘defaultTimeLocale’
    In the first argument of ‘(<$>)’, namely
      ‘formatTime defaultTimeLocale timeFormat’

src/System/Log/Formatter.hs:75:40:
    Couldn't match expected type ‘time-1.5:Data.Time.Format.Locale.TimeLocale’
                with actual type ‘System.Locale.TimeLocale’
    NB: ‘time-1.5:Data.Time.Format.Locale.TimeLocale’
          is defined in ‘Data.Time.Format.Locale’ in package ‘time-1.5’
        ‘System.Locale.TimeLocale’
          is defined in ‘System.Locale’ in package ‘old-locale-1.0.0.6’
    In the first argument of ‘formatTime’, namely ‘defaultTimeLocale’
    In the first argument of ‘(<$>)’, namely
      ‘formatTime defaultTimeLocale timeFormat’

There's also no upper bound on the dependency, leading to broken builds for packages that depend on hslogger.

I find that 97% of all my log messages are priority DEBUG. It could be handy to have a few priorities lower than that.

The main concern here is speed and efficiency. Many performance-critical production scenarios should not be working with String. Convenience is a secondary concern.

Could there be any interest in moving to a typeclassed API that natively implements the most efficient method to push log strings of each type?

I use metalog http://metalog.sourceforge.net/ on my development machines so I don't have to fiddle with logrotate all the time. I noticed that the following doesn't log anything when using metalog:

  Prelude> :set prompt "ghci> "
  ghci> :m +System.Log.Logger
  ghci> :m +System.Log.Handler.Syslog
  ghci> sl <- openlog rootLoggerName [] USER DEBUG
  ghci> updateGlobalLogger rootLoggerName (addHandler sl)
  ghci> errorM rootLoggerName "This won't show up with metalog."

If however I stop metalog and start syslog-ng, everything works as expected.

It turned out that GHC by default does "no buffering" for stderr, and for hslogger this might be a huge performance-bottleneck.

Here's an example of a script that confirms performance problems: https://gist.github.com/k-bx/ccf6fd1c73680c8a4345 (please, don't pay any attention to "timeout" thing, initiall I thought the problem lies in concurrent usage of hslogger).

In order to resolve problem, you can either manually put hSetBuffering stderr LineBuffering in your program, or disable logging to stderr at all.

I think that hslogger should do its best in order to not put a person into a situation when logging consumes huge amount of time, and I would propose to somehow determine that user is willing to use logging to stderr and in that case doing hSetBuffering stderr LineBuffering in order to switch buffering to LineBuffering mode.

Shouldn't the semantics be such that the parent loggers are consulted per their log levels? The current implementation bypasses the parent loggers and goes to their Handlers directly.

Consider that:

• rootLogger is initiated with a DEBUG level stderr logger
• Therefore any logger in the system with a higher log level will implicitly log to stderr, even if the rootLogger level is set to WARNING or anything higher.
• Notice how this bypasses the sensical check "Does the parent have adequate log level for this message?" It is enough for the parent's Handler to have adequate level, which is confusing.
• There is no easy way to turn this off - one is forced to overwrite rootLogger handlers with setHandlers [] :: [GenericHandler Handle], which is just ugly.

The Cabal flag buildtests duplicates the exact same functionality as the --enable-tests flag to cabal. Unless I'm missing something, I believe you could just remove that without losing any functionality.

There seem to be a lot of small things that need fixing. Saw warnings about redundant imports, non-exhaustive pattern matches, non-used and shadowed variables, ...

This would enable listing priorities using [minBound .. maxBound :: Priority], which is a handy idiom for that sort of thing.

Latest version fails with:

[4 of 8] Compiling System.Log.Handler.Growl ( src/System/Log/Handler/Growl.hs, dist/build/System/Log/Handler/Growl.o )

src/System/Log/Handler/Growl.hs:21:1: error:
    Could not load module ‘Network.BSD’
    It is a member of the hidden package ‘network-2.8.0.0’.
    Perhaps you need to add ‘network’ to the build-depends in your .cabal file.
    Use -v to see a list of the files searched for.
   |
21 | import Network.BSD
   | ^^^^^^^^^^^^^^^^^^

The Network.BSD module now lives in the network-bsd package.

Network.Socket.sendBufTo does not exist (no such file or directory)

Currently the bound base < 4.16 on the latest version 1.3.1.0 prevents building with GHC 9.2.

In this example:

import           System.Log                (Priority (DEBUG))
import           System.Log.Formatter      (simpleLogFormatter)
import           System.Log.Handler        (setFormatter)
import           System.Log.Handler.Simple (fileHandler)
import           System.Log.Handler.Syslog (Facility (USER), Option (PID),
                                            openlog)
import           System.Log.Logger         (addHandler, debugM, errorM,
                                            rootLoggerName, setLevel,
                                            updateGlobalLogger)

main :: IO ()
main = do
  -- s <- openlog "PlaySyslog" [PID] USER DEBUG
  s <- openlog "PlaySyslog" [PID] USER DEBUG >>= \lh -> return $
    setFormatter lh (simpleLogFormatter "[$time : $loggername : $prio] $msg")
  fh <- fileHandler "debug.log" DEBUG >>= \lh -> return $
    setFormatter lh (simpleLogFormatter "[$time : $loggername : $prio] $msg")
  updateGlobalLogger rootLoggerName (addHandler s)
  updateGlobalLogger rootLoggerName (addHandler fh)
  updateGlobalLogger rootLoggerName (setLevel DEBUG)
  debugM "Foo.Bar" "Hi!"
  errorM "Foo.Bar" "Wow! An error!"
  return ()

for some reason, if you do setFormatter on syslog -- it just stops working (nothing appears in syslog). If, however, you don't do setFormatter -- it writes to syslog just fine (but with default formatting).

Did I miss something?

Thanks!

I'm trying to install hslogger, using the command cabal install hslogger-1.2.10. However, it doesn't work -- it tells me hlogger-1.2.10 failed during the building phase. The exception was: ExitFailure 1.

Any idea why this is happening? I need hslogger to get MissingH.

I'm on macOS Sierra, if that's of any use.