SubLogger are not flexible enough

[chaen]

Basically the problem is illustrated with the following example:

  import gLogger
  gLogger.setLevel('DEBUG')
  # log has level debug
  log = gLogger.getSubLogger('log')

  sublog = log.getSubLogger('sublog')
  sublog.setLevel('INFO')

  log.error("changeLevel")
  # should print "Framework/log ERROR: changeLevel"
  sublog.error("changeLevel")
  # should print "Framework/sublog ERROR: changeLevel"

  log.debug("changeLevel")
  # should print "Framework/log DEBUG: changeLevel"
  sublog.debug("changeLevel")
  # should NOT print    "Framework/sublog DEBUG: changeLevel"

Even though the last line should not be printed, it is.
The reason is that sublog.setLevel loops over the Backends of sublog, and set their level to INFO. However, there is no backend attached to sublog ! Yet the message are displayed because the logger object of sublog has the value propagate to True (https://docs.python.org/2/library/logging.html#logging.Logger.propagate). In practice, this mean that we cannot really change levels or options of sublogers.

The levels are managed in a strange way: the logger level is always debug, and a Logging.setLevel just changes the level of the Backends (so of the handlers). This was done in order to make sure that the centralized logging could not be disabled.

I cannot think of a way to make our code work, while not re-implementing basically what logging does, which is exactly what we want to avoid.
Setting propagate to False would mean duplicating the backend to the child, which is not necessarily thread safe (think of the logs being written to a file: there would be several file handlers on the same file).
Creating FacadeBackend to just pretend that the parent backend belongs to the child is also not an option, because we would still not be able to change the level of subloggers.

From the top of my head, the only option I see is to relax the constraint we have on the centralized logging, and accept that some stuff may get disabled by the developers...

I keep this as a note for me for later

[andresailer]

There are the LogFilters which can be set for backends, but not dynamically during runtime
https://dirac.readthedocs.io/en/latest/CodeDocumentation/Resources/LogFilters/ModuleFilter.html

[chaen]

yeah and also it it has the drawback of needing the whole level to be debug

[fstagni]

One more (weird) piece:

In [13]: sublog.info('aaa')
2020-04-03 15:32:43 UTC Framework/log/sublog INFO: aaa
Out[13]: True

In [14]: sublog.debug('aaa')
2020-04-03 15:32:45 UTC Framework/log/sublog DEBUG: aaa
Out[14]: False

sublog.debug('aaa') returns False after having printed a debug message.

[phicharp]

Another feature to maybe change is the fact that the method showHeaders() triggers both the timestamp and the context header to be printed...
There are occasions (e.g. within scripts, where showHeaders() is disabled by default) when we would like to have the context but not necessarily the timestamp as for a script it is rather useless...
I would suggest to add 2 methods showTimestamp() and showContext() for example while showHeaders() would call both... Of course this should work for subLoggers independently.

[aldbr]

TL;DR

If we want the possibility to gather all logs in some backends like ElasticSearch, we should implement
see Attach a filter to the backends:

• safest option
• need to completely redefine the level mechanism of logging in DIRAC

If gathering all logs is not so important, then we should keep the level mechanism of logging as it is:
see Simply use the logging level

• keep it simple
• logs gathered will mainly depend on gLogger level but also on sublogger levels when they are modified

Any comment? Question? Preference?

List of possibilities to fix the issues related to the level:

Use backend level as logger level (Current)

• every logger level is DEBUG and cannot be modified
• only backend level is set
• when setLevel() is called, the level of the backends attached to a logger is modified

Pros

• some backends (those that don't allow to set their level) like ElasticSearch can receive all the generated logs

Cons

• complete redifinition of the level
• in DIRAC, backends are only attached to gLogger actually, thus setLevel() does not work as we expect in the subloggers:

gLogger.setLevel('notice')
log = gLogger.subLogger('log')
gLogger.notice('msg')
log.notice('msg')

> '... msg'
> '... /log: msg'

log.setLevel('error')
gLogger.notice('msg')
log.notice('msg')

> '... msg'
> '... /log: msg' # should not appear

Disable the log propagation, add the gLogger backends to the children (copy)

• every logger level set to DEBUG and cannot be modified
• only backend level is set
• when setLevel() is called, the level of the backends attached to a logger is modified
• logging.propagate is set to False, log records are not propagated to the father logger
• backends attached to the father are copied and attached to the children

Pros

• some backends (those that don't allow to set their level) like ElasticSearch can receive all the generated logs

Cons

• redefinition of the logging level
• we can have multi-threads issues: 2 backends trying to write on the same file

Disable the log propagation, add the gLogger backends to the children (reference)

• every logger level set to DEBUG and cannot be modified
• only backend level is set
• when setLevel() is called, the level of the backends attached to a logger is modified
• logging.propagate is set to False, log records are not propagated to the father logger
• backends attached to the father are referenced in the children (not copied this time)

Pros

• some backends (those that don't allow to set their level) like ElasticSearch can receive all the generated logs

Cons

• redefinition of the logging level

Attach a filter to the backends

• every logger level set to DEBUG and cannot be modified
• a "new" level is defined in each logger and passed to construct the log records
• a filter, attached to backends (except those that need to receive all the logs), is in charge of accepting or rejecting the log depending on the value of the "new" level
• when setLevel() is called, the "new" level is modified

Pros

• some backends (those that don't allow to set their level) like ElasticSearch can receive all the generated logs

Cons

• redefinition of the logging level ++

Redefinition of logger level only for LoggingRoot

• level is only redefined for Logging Root
• when setLevel() is called on a logger, it changes its level
• when setLevel() is called on loggingRoot, it changes the level of the backends, its own level is set to DEBUG

Pros

• can receive all the logs from gLogger but not from subloggers if their level is modified

Cons

• partial but existing redefinition of the level
• some backends like ElasticSearch don't receive all the generated logs
• two implementations of setLevel() can create discrepancies and issues:

gLogger.setLevel('notice')
log = gLogger.subLogger('log')
gLogger.debug('msg')
log.debug('msg')

> 
> 

log.setLevel('debug')
gLogger.debug('msg')
log.debug('msg')

> 
> # '... /log: msg' should have appeared but have been blocked by the backend level that corresponds to gLogger redefined level

Simply use the logging level
Pros

• no redefinition of the logging level: make gLogger simpler
• no discrepancy, no issue from gLogger on this point

Cons

• some backends (those that don't allow to set their level) like ElasticSearch will not be able to receive all the generated logs

[chaen]

In my opinion, we should go towards using more logging, and get rid of all the complexity on top.

There is maybe something in between though.
What normally happens is that we set do a setLevel at the very beginning:

• starting a script with -d+
• launching a component, with the level defined in the CS (or in the cmd line)

I believe all these initial steps are done using what you called the RootLogger.

Then, the use case we now have is to get a sublogger, and changing the level/headers for that sublogger only, without impacting the rest. And it is typically done only for debugging purpose.
So what we could do is:

• get rid of all the level management in DIRAC
• when doing the initial setLevel at configure time, we set the level of the backend, which in turns simply set the level of the logging handlers, (except for the MQ or ES backend, where it does nothing). This is to be implemented in the RootLogger
• Any other call to setLevel to any sublogger would simply set the level of the logging class itself.

As for the return value issue mentionned by Federico

One more (weird) piece:

In [13]: sublog.info('aaa')
2020-04-03 15:32:43 UTC Framework/log/sublog INFO: aaa
Out[13]: True

In [14]: sublog.debug('aaa')
2020-04-03 15:32:45 UTC Framework/log/sublog DEBUG: aaa
Out[14]: False

sublog.debug('aaa') returns False after having printed a debug message.

I think this was an addon later just for a silly single use case. It should be dropped

For the showHeader

Another feature to maybe change is the fact that the method showHeaders() triggers both the timestamp and the context header to be printed...
There are occasions (e.g. within scripts, where showHeaders() is disabled by default) when we would like to have the context but not necessarily the timestamp as for a script it is rather useless...
I would suggest to add 2 methods showTimestamp() and showContext() for example while showHeaders() would call both... Of course this should work for subLoggers independently.

Adding the options (showHeader, etc) in the extraArgs instead of having them properties of the Backend is probably an option, I did not give it much thought, but it would also work for the backend then.

what do you think ?

[aldbr]

About the level:

Then, the use case we now have is to get a sublogger, and changing the level/headers for that sublogger only, without impacting the rest. And it is typically done only for debugging purpose.
So what we could do is:

• get rid of all the level management in DIRAC
• when doing the initial setLevel at configure time, we set the level of the backend, which in turns simply set the level of the logging handlers, (except for the MQ or ES backend, where it does nothing). This is to be implemented in the RootLogger
• Any other call to setLevel to any sublogger would simply set the level of the logging class itself.

There is an issue with this solution that I've described in Redefinition of logger level only for LoggingRoot in my previous comment, here is an example:

# gLogger level has been set to NOTICE
# (so actually, handlers attached to LoggingRoot have been set to NOTICE)

# we define a sublogger called 'log'
log = gLogger.subLogger('log')

# DEBUG < NOTICE: they should not appear
gLogger.debug('msg gLogger')
log.debug('msg log')
> 
> 

# Let's say for debugging purpose we set log level to DEBUG 
# (the `logging` level in this case)
log.setLevel('debug')
gLogger.debug('msg gLogger')
log.debug('msg log')

# We would expect to have 'msg log' right?
> 
>
# But nothing would appear because 'msg log' is propagated
# to the handlers attached to LoggingRoot that only accept 
# log records from NOTICE and above

About showHeaders

Adding the options (showHeader, etc) in the extraArgs instead of having them properties of the Backend is probably an option, I did not give it much thought, but it would also work for the backend then.

I've made the change in a branch, I've used the extraArgs of the log records instead of the Backend properties, it seems more natural than the current behavior.
I will add showTimeStamp() and showContext() in the same way.
Once we will agree on how the level mechanism should work, I will make the PR

[chaen]

Argh !! I've read too fast sorry ! Indeed, you already proposed the solution and described the problem :D It needs more thought then :-)

[fstagni]

Can this issue be closed now?

[chaen]

I assume it can