[Haskell-cafe] Re: hslogger bugs or features?

John Goerzen jgoerzen at complete.org
Tue Feb 3 10:15:37 EST 2009


Marc Weber wrote:
> Following the advice on the hslogger wiki
> (http://software.complete.org/software/wiki/hslogger)
> I'm posting my thoughts about hslogger here:

Hi Marc,

Thanks for posting this.

Let's start with a big-picture architecture overview.  What need does
hslogger anticipate meeting?

* Big applications have varied logging needs.

* Small applications want to keep logging simple.

* It is often desirable to enable or disable logging about certain types
of things.

* It is also often desirable to enable or disable logging above a
certain threshold of importance.

* The vast majority of apps want to set logging preferences once and
then forget about them, having decided what to do by reading a config
file, command line, or whatever.

* There can be many different ways to output logging messages: syslog,
stderr, files, etc.  A given app may want to use more than one of them.

There are a lot of logging frameworks out there.  Many of them fail the
"keep logging simple" test.  Many others fail the "varied needs" test.
One that failed neither in my experience was the Python logging
infrastructure, so I based hslogger around its interface.  hslogger has
served me pretty well since, though I wish it were a bit stronger on the
simple side.


> This piece of code (src/System/Log/Logger.hs):
> 
>        parentHandlers name =
>             let pname = (head . drop 1 . reverse . componentsOfName) name
>                 in do 
>                 [...]
>                 next <- parentHandlers pname
>                 return ((handlers parent) ++ next)
> 
> Why?
> Because when logging to "A.B.C" it splits the String once to get
> ["A","B","C"], then it drops the last part and runs the same again for
> "A.B" and so on..
> So A string is split > 3 times for one logging action. I think this is a
> waste of cpu cycles.. I'm going to improve this. While reading the code
> i noticed two issues:

It may be, but really this is trivially tiny.  The effort required to do
that is almost certainly exceptionally tiny compared just to the effort
required to actually output the log message.  If you have a simple fix,
that's fine, but let's not complicate the code to save a 2 CPU cycles in
a process that can't possibly use less than 1000 :-)

> ======================================================================
> issue 1
> 
> That's not the most awkward thing:
>   When logging to "A.B.C" hslogger does add 3 loggers to the global
>   logger Map:

Only if you haven't logged to it before.

>   "A"
>   "A.B"
>   "A.B.C"
>   all three inheriting the default priority level of the default
>   rootLogger ""

According to the docs:

  First of all, whenever you first access a given logger by name, it
  magically springs to life.  It has a default 'Priority' of 'DEBUG'
  and an empty handler list -- which means that it will inherit whatever
  its parents do.

It's not setting the priority to the rootLogger default; it's setting it
to DEBUG.  Your test doesn't invalidate this.

> A test application illustrating this (feature ?)
> 
>   module Main where
>   -- packages: hslogger
>   import  System.Log.Logger as HL
>   import  System.Log.Handler.Simple as HL
> 
>   main = do
>     -- the default logger logs to stderr level WARNING 
>     -- that's why the following message should be shown 
> 
>     -- a)
>     logM "A.B.C" HL.ALERT "ALERT test, should be shown and should create the sublogger"
> 
>     -- b)
>     updateGlobalLogger rootLoggerName (setLevel EMERGENCY)
> 
>     logM "A.B.C" HL.ALERT "ALERT test, should not be shown cause we have changed to EMERGENCY"
> 
> which prints:
> 
>   tmp %./test1
>   /tmp nixos   
>   ALERT test, should be shown and should create the sublogger
>   ALERT test, should not be shown cause we have changed to EMERGENCY
> 
> which is quite confusing because I haven't told hslogger explicitely
> to use a log level printing ALERTs on "A.B.C". so I'd expect that only

No, you told it that things logged to the root logger directly have a
certain preference.  You have never expressed any preference whatsoever
on the A.B.C logger.

If you wish to set a global preference on the level of logging to occur,
you would be better served to do so in the configuration for the
handler.  From the docs:

  To give you one extra little knob to turn, 'LogHandler's can also have
  importance levels ('Priority') associated with them in the same way
  that 'Logger's do.  They act just like the 'Priority' value in the
  'Logger's -- as a filter.  It's useful, for instance, to make sure
  that under no circumstances will a mere 'DEBUG' message show up in
  your syslog.

Since handlers are inherited down the logger chain, you can easily tweak
the priority associated with the handlers at the root logger level and
have an instant impact on all the others.

The point of the priority attached to a logger is to be able to disable
messages *about* certain things.

The point of the priority attached to a handler is to be able to disable
messages *below a certain importance level globally*.

So I think you're trying to turn the wrong knob to achieve your desired
goal.

> ======================================================================
> issue 2
> 
> The second ineresting point is (bug or feature?) that you can make the
> root logger shut up by setting different log levels to sub loggers:
> 
> this sample does illustrate it:

It doesn't illustrate that.  You logged to the "A" logger, not the root
logger.  Let's look at it below.

> 
>   module Main where
>   -- packages: hslogger
>   import  System.Log.Logger as HL
>   import  System.Log.Handler.Simple as HL
> 
>   main = do
>     updateGlobalLogger "" (setLevel DEBUG)
>     updateGlobalLogger "A" (setLevel EMERGENCY)
>     logM "A" HL.ALERT "ALERT test, should not be shown cause we have
>   changed to EMERGENCY"

> It doesn't print anything although the default log handler on root (="")
> is set to loglever DEBUG. So there is no way to get all logmessages

So what you've done here is tell hslogger that for log events regarding
"A", you don't want to hear about anything unless it's an EMERGENCY.
And hslogger followed your instructions directly.

> without removing all all setLevel calls to subloggers?
> Is this desirable?

I don't understand the problem.  If you told hslogger that you didn't
want to hear about stuff about "A", why do you not like that it is
following your instructions?

Note that you didn't actually change the priority of the handler up
there.  You changed the priority of the *logger*.  Remember, logger
priorities aren't inherited.

As I said, I think your whole problem would be solved if you simply
changed the priority of the handler associated with the root logger.

-- John


More information about the Haskell-Cafe mailing list