salt.client mess with logging

[KeepMasterBranch]

tested on 0.14.0

import logging
import sys
import salt.client
logger = logging.getLogger()
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG, format="Debug: %(message)s")
logger.debug("Test")

Nothing show, but if I move salt.client import just after the logging is initialized:

import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.DEBUG, format="Debug: %(message)s")
import salt.client

logger = logging.getLogger()
logger.debug("Test")

I get:

Debug: Test

[s0undt3ch]

You know how a building is imploded?
It's a mess right?
A controlled mess.

You might think salt's logging is also a mess... at most, a controlled one.

Salt does try to make python's logging work for it.
We try to overcome some common obstacles.

I'll explain what exactly has happened with the above code.
When salt.log get's imported(by importing salt.client), it installs a Null logging handler, if, there's no logging handler already configured(your 2nd example).
This is required so we don't get errors like, no handler for _foo_, which happens when we try to log too soon.

There's some more _black_ magic with salt's logging, so, the real question is, what exactly are you trying to achieve in which salt's logging is getting in your way?

If you're trying to integrate salt in your own library, either setup your own logging before importing salt, or, as suggested here, import it really soon, then use salt.log.setup_console_logger and/or salt.log.setup_logfile_logger to configure it, also, as soon as possible.

[KeepMasterBranch]

I didn't said here that salt logging is a mess.

I was considering salt.client as a library that can be imported and use like any other. I never had this issue before with an other Python library, in stdlib or not.

check here:

http://docs.python.org/2/howto/logging.html#configuring-logging-for-a-library

Unless salt.client isn't a library.

Usually, loggers are initialized by the consumer of those libraries, such as salt-master, salt-minion, salt-run or salt-call. Or in my case, my own code.

I never had to configure loggers before import anything from boto, django or stdlib that is in their API.

So, if I write a python library that import salt.client, I always have to initialize logging _before_ import my own library?

Logging to console or a log file, aren't the only 2 usage of python logging library. In my case, I wrote some unittest that execute salt state to test them and I wanted to report error to sentry (using raven logger) and send email to me directly if one of my logger log an error.

[ahammond]

I would pay in blood to have logging configurable to support the zeromq appender for logstash: https://github.com/mattmcclean/logstash-python

[thatch45]

As much as I appreciate your enthusiasm, the currency of the realm, is currency :)

[KeepMasterBranch]

Well, in this case, a library shouldn't initialize logging, as said here: http://docs.python.org/2/howto/logging.html#configuring-logging-for-a-library

but to get a logstash handler (and for me to get a raven handler [to receive logs with error level in sentry] and graypy handler [to get logs in graylog2]), the minion, master, syndic, salt-call, salt-run, etc should all initialize logging with logging.config.dictConfig and the dict defined in /etc/salt/$config.

[s0undt3ch]

Let's clarify this issue.

As suggested by the logging library, the link you posted @bclermont, and I quote:

If the using application does not configure logging, and library code makes logging calls, then
(as described in the previous section) an error message will be printed to sys.stderr.

If for some reason you don’t want this message printed in the absence of any logging configuration,
you can attach a do-nothing handler to the top-level logger for your library. This avoids the message
being printed, since a handler will be always be found for the library’s events: it just doesn’t produce
any output.

That said, as soon as you import any salt module, we import salt.log(this line).
The repercussion of that import is that:

• we define 2 more logging level constants here, trace and garbage which are lower than debug
• we create a one-to-one copy of python's 2.7 logging null handler in case we're using python 2.6, here, since it does not exist in 2.6
• we instantiate a NullHandler to keep a reference to it, here, so we can later remove it, and only our own handler
• we instantiate a temporary sys.stderr stream handler here, so we can later remove it, and only our own handler
• we define a helping logging class here and set it as the default logging class here, were we also:
  
  
  
  • add the previously defined logging level constants(here)
  
  
  • we set the root logger to garbage level so we catch all logging messages, even those not being logged by salt, ie, by external libraries in the current interpreter's scope.
  
  
  • check for any previously configured logging handlers. If none is found, install the null logging handler, which is what python's logging documentation, the link you posted, states you should do, we just avoid doin' it if there's already any logging handler.
  
  

>>> import logging
>>> logging.getLoggerClass()
<class 'logging.Logger'>
>>> logging.root.handlers
[]
>>> import salt.client
>>> logging.root.handlers
[<logging.NullHandler object at 0xb71ff1ec>]
>>> logging.getLoggerClass()
<class 'salt.log.SaltLoggingClass'>
>>>

So, although we're doin' some more stuff, like setting the default logging class, adding the extra levels, and setting the root logger level to garbage, we're actually following the python's logging documentation regarding the null handler.

No other logging configuration and/or tweak is done. The only thing I could find(on a fast search) is this line of code which set's up the temporary logging handler but is only triggered if msgpack is not installed.

Other than that, any further logging configuration is only done on CLI access code like salt.utils.parsers.

Regarding dictConfig, we've already discussed this here @bclermont. Although the formatting of my reply is not the best here in GitHub, it reads better in the email, I'll remember the conclusion:

I basically said, I'm not going to do it(at least, not right now), not because you're wrong,
but because the need for that much power was asked by a single user, you.
So, since it's only you, since there's no "massive" request for it, since it's more error
prone for the overall salt users, and since salt itself, currently, does not require those
changes, we accept pull requests. You're free to add that support to salt, we will be
more than glad to review your pull request and include it in salt's code.

It still applies. A LOT more has fallen in my hands, it's still not on the top of my priority list. But we _still_ accept pull requests :smile:

[ahammond]

I have some free time this weekend. Where would I look in the code-base to add dictConfig support? Also, why dictConfig over fileConfig?

[s0undt3ch]

dictConfig because dictionaries can be pulled from salt's yaml config.

fileConfig could also be used and have it's path configured in salt config.

I think it's a matter of preference.

Regarding where, logging config should go in salt.log, cli config should go in salt.utils.parsers or salt.config if possible or salt.cli, its a matter of what needs to be done.

[stephen-mw]

I had an issue with this as well. The workaround (instantiating the logging object right before importing salt modules) worked for me. Without that I wasn't getting any output from my flask application.

[s0undt3ch]

@stephendotexe I'm late on creating a document which explains that procedure and other particularities about salt logging. Sorry.

[uvsmtid]

+1
It took me some time to figure this out.
Should it rather be a bug than a feature?

#!/usr/bin/env python
import logging
# Without this line `salt.client` somehow prevents all subsequent `logging` output.
logging.debug('initialize logging')
# Salt modules.
import salt.client
# ... other imports

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.

[mcarlton00]

This is still a bug and still present as far as I can tell. At the very least this needs to be documented on the salt client page if it's not going to be changing, because it's not expected behavior in most non-salt python modules.

Nonworking Example:

import logging
import salt.client

print('before logger')

logging.basicConfig(
    format='%(asctime)s %(levelname)s:%(message)s',
    datefmt='%m/%d/%Y %I:%M:%S %p',
    level=logging.INFO)

logging.info('info')
logging.warning('warning')
logging.error('error')

print('after logger')

Output:

$ python example.py
before logger
after logger

Working Example:

import logging

print('before logger')

logging.basicConfig(
    format='%(asctime)s %(levelname)s:%(message)s',
    datefmt='%m/%d/%Y %I:%M:%S %p',
    level=logging.INFO)

import salt.client

logging.info('info')
logging.warning('warning')
logging.error('error')

print('after logger')

Output:

$ python example.py
before logger
01/29/2020 09:40:32 AM INFO:info
01/29/2020 09:40:32 AM WARNING:warning
01/29/2020 09:40:32 AM ERROR:error
after logger

[s0undt3ch]

Care to open a new issue requesting a documentation clarification please?

Salt is not a library, though it can be used as one, and the working example you posted is how you can use it as a library with regards to the expected logging behavior of libraries.